diff --git a/btrace-android/rhea-library/rhea-inhouse/src/main/java/com/bytedance/rheatrace/trace/base/TraceGlobal.java b/btrace-android/rhea-library/rhea-inhouse/src/main/java/com/bytedance/rheatrace/trace/base/TraceGlobal.java index 596bf9f..9c55970 100644 --- a/btrace-android/rhea-library/rhea-inhouse/src/main/java/com/bytedance/rheatrace/trace/base/TraceGlobal.java +++ b/btrace-android/rhea-library/rhea-inhouse/src/main/java/com/bytedance/rheatrace/trace/base/TraceGlobal.java @@ -32,7 +32,7 @@ public class TraceGlobal { nativeInit(Looper.getMainLooper().getThread()); JNIHook.init(); success = true; - } catch (Exception e) { + } catch (Throwable e) { Log.e(TAG, "rhea-trace init failed: ", e); success = false; } @@ -51,4 +51,4 @@ public static void capture(boolean force) { } private static native void nativeCapture(boolean force); -} \ No newline at end of file +} diff --git a/btrace-iOS/BTraceTool/btrace/app.py b/btrace-iOS/BTraceTool/btrace/app.py index 05a48f9..524ec14 100644 --- a/btrace-iOS/BTraceTool/btrace/app.py +++ b/btrace-iOS/BTraceTool/btrace/app.py @@ -95,7 +95,7 @@ def stop_record() -> Optional[bytes]: url = util.API_HOST + "/record/stop" config = {} - resp = requests.post(url, json=config, timeout=30) + resp = requests.post(url, json=config, timeout=60) resp.raise_for_status() gz_data = resp.content diff --git a/btrace-iOS/BTraceTool/btrace/cli.py b/btrace-iOS/BTraceTool/btrace/cli.py index c35897d..f4a884c 100644 --- a/btrace-iOS/BTraceTool/btrace/cli.py +++ b/btrace-iOS/BTraceTool/btrace/cli.py @@ -79,6 +79,7 @@ def cmd_record(args): device_id = args.device_id bundle_id = args.bundle_id + frequency = args.frequency time_limit = args.time_limit or 3600 hitch = args.hitch or 50 hitch = max(hitch, 33) @@ -86,8 +87,12 @@ def cmd_record(args): launch = args.launch next_launch = args.next_launch verbose = args.verbose + upload = args.upload util.set_verbose(verbose) + + if util.verbose(): + print("args: ", args) device_info = {} @@ -164,7 +169,7 @@ def cmd_record(args): pid = device.connect_if_need(device_id) pid_list.append(pid) - util.set_record_parameter(main_thread_only, hitch) + util.set_record_parameter(main_thread_only, hitch, frequency) if launch: app.launch(device_id, bundle_id) @@ -188,7 +193,7 @@ def signal_stop(signum, frame): signal.signal(signal.SIGINT, signal_stop) - print(f"Press cltr+c to stop") + print(f"Press ctrl+c to stop") interval = 0.5 record_time = 0 @@ -218,10 +223,11 @@ def cmd_parse(args): sys_symbol = args.sys_symbol force = args.force verbose = args.verbose + upload = args.upload util.set_verbose(verbose) - parse(file_path, dsym_path, force, sys_symbol) + parse(file_path, dsym_path, force, sys_symbol, upload) def cmd_export(args): @@ -274,6 +280,7 @@ def main(): "-H", "--hitch", dest="hitch", type=int, help="hitch thres" ) record_parser.add_argument("-d", "--dsym_path", dest="dsym_path", help="dsym dir") + record_parser.add_argument("-f", "--frequency", dest="frequency", help="frequency, e.g., 1ms, 100us") record_parser.add_argument( "-m", "--main_thread_only", @@ -293,6 +300,9 @@ def main(): record_parser.add_argument( "-v", "--verbose", dest="verbose", action="store_true", help="show verbose info" ) + record_parser.add_argument( + "-u", "--upload", dest="upload", action="store_true", help="upload trace file" + ) # parse parser_lib = subparser.add_parser("parse", help="parse trace data") @@ -307,6 +317,9 @@ def main(): parser_lib.add_argument( "-v", "--verbose", dest="verbose", action="store_true", help="show verbose info" ) + parser_lib.add_argument( + "-u", "--upload", dest="upload", action="store_true", help="upload trace file" + ) # export export_lib = subparser.add_parser("export", help="export trace data") diff --git a/btrace-iOS/BTraceTool/btrace/extractor.py b/btrace-iOS/BTraceTool/btrace/extractor.py index a7cd62c..981ca72 100644 --- a/btrace-iOS/BTraceTool/btrace/extractor.py +++ b/btrace-iOS/BTraceTool/btrace/extractor.py @@ -28,6 +28,7 @@ ImageInfo, IntervalSampleNode, LockAction, + LockContentionPair, LockSample, LockSampleNode, MemSample, @@ -41,6 +42,8 @@ TimeRangeSample, TimeRangeSampleNode, TraceRawContent, + IOSample, + IOSampleNode, image_info_key, sample_info_key, ) @@ -58,6 +61,8 @@ cpu_batch_interval_sample_table_name = "CPUBatchIntervalSampleModel" mem_sample_table_name = "MemSampleModel" mem_batch_sample_table_name = "MemBatchSampleModel" +mem_alloc_sample_table_name = "MemAllocSampleModel" +mem_alloc_batch_sample_table_name = "MemAllocBatchSampleModel" date_sample_table_name = "DateSampleModel" date_batch_sample_table_name = "DateBatchSampleModel" lock_sample_table_name = "LockSampleModel" @@ -70,6 +75,8 @@ profile_batch_sample_table_name = "ProfileBatchSampleModel" time_range_sample_table_name = "TimeRangeSampleModel" time_range_batch_sample_table_name = "TimeRangeBatchSampleModel" +io_sample_table_name = "IOSampleModel" +io_batch_sample_table_name = "IOBatchSampleModel" def gen_callstack_map(callstack_table: bytes) -> Dict[int, CallstackNode]: @@ -673,6 +680,85 @@ def gen_mem_sample_list_v3(mem_sample_bytes: bytes) -> List[MemSampleNode]: return result +def gen_mem_sample_list_v4(sample_bytes: bytes) -> List[MemSampleNode]: + result: List[MemSampleNode] = [] + step_size = 4 + for idx in range(0, len(sample_bytes), 7 * step_size): + time = int.from_bytes(sample_bytes[idx : idx + step_size], byteorder="little") + cpu_time = int.from_bytes( + sample_bytes[idx + step_size : idx + 2 * step_size], + byteorder="little", + ) + alloc_size = int.from_bytes( + sample_bytes[idx + 2 * step_size : idx + 3 * step_size], + byteorder="little", + ) + alloc_count = int.from_bytes( + sample_bytes[idx + 3 * step_size : idx + 4 * step_size], + byteorder="little", + ) + stack_id = int.from_bytes( + sample_bytes[idx + 4 * step_size : idx + 5 * step_size], + byteorder="little", + ) + alloc_addr = int.from_bytes( + sample_bytes[idx + 5 * step_size : idx + 6 * step_size], + byteorder="little", + ) + curr_size = int.from_bytes( + sample_bytes[idx + 6 * step_size : idx + 7 * step_size], + byteorder="little", + ) + + time *= 10 + cpu_time *= 10 + + result.append( + MemSampleNode(alloc_addr, curr_size, time, cpu_time, stack_id, alloc_size, alloc_count) + ) + + return result + + +def gen_mem_alloc_sample_list_v4(sample_bytes: bytes) -> List[MemSampleNode]: + result: List[MemSampleNode] = [] + step_size = 4 + for idx in range(0, len(sample_bytes), 8 * step_size): + time = int.from_bytes(sample_bytes[idx : idx + step_size], byteorder="little") + cpu_time = int.from_bytes( + sample_bytes[idx + step_size : idx + 2 * step_size], + byteorder="little", + ) + alloc_size = int.from_bytes( + sample_bytes[idx + 2 * step_size : idx + 3 * step_size], + byteorder="little", + ) + alloc_count = int.from_bytes( + sample_bytes[idx + 3 * step_size : idx + 4 * step_size], + byteorder="little", + ) + stack_id = int.from_bytes( + sample_bytes[idx + 4 * step_size : idx + 5 * step_size], + byteorder="little", + ) + alloc_addr = int.from_bytes( + sample_bytes[idx + 5 * step_size : idx + 7 * step_size], + byteorder="little", + ) + curr_size = int.from_bytes( + sample_bytes[idx + 7 * step_size : idx + 8 * step_size], + byteorder="little", + ) + + time *= 10 + cpu_time *= 10 + + result.append( + MemSampleNode(alloc_addr, curr_size, time, cpu_time, stack_id, alloc_size, alloc_count) + ) + + return result + def gen_interval_sample_list(interval_sample_bytes: bytes) -> List[IntervalSampleNode]: result: List[IntervalSampleNode] = [] step_size = 4 @@ -908,6 +994,46 @@ def gen_cpu_sample_list_v3(sample_bytes: bytes) -> List[SampleNode]: return result +def gen_io_sample_list_v4(sample_bytes: bytes) -> List[IOSampleNode]: + result: List[IOSampleNode] = [] + step_size = 4 + for idx in range(0, len(sample_bytes), 7 * step_size): + time = int.from_bytes(sample_bytes[idx : idx + step_size], byteorder="little") + cpu_time = int.from_bytes( + sample_bytes[idx + step_size : idx + 2 * step_size], + byteorder="little", + ) + alloc_size = int.from_bytes( + sample_bytes[idx + 2 * step_size : idx + 3 * step_size], + byteorder="little", + ) + alloc_count = int.from_bytes( + sample_bytes[idx + 3 * step_size : idx + 4 * step_size], + byteorder="little", + ) + stack_id = int.from_bytes( + sample_bytes[idx + 4 * step_size : idx + 5 * step_size], + byteorder="little", + ) + type = int.from_bytes( + sample_bytes[idx + 5 * step_size : idx + 5 * step_size + 1], + byteorder="little", + ) + size = int.from_bytes( + sample_bytes[idx + 5 * step_size + 1: idx + 7 * step_size], + byteorder="little", + ) + + time *= 10 + cpu_time *= 10 + + result.append( + IOSampleNode(time, cpu_time, stack_id, alloc_size, alloc_count, type, size) + ) + + return result + + def table_exists(con: sqlite3.Connection, table_name: str) -> bool: table_exist_sql = f'select count(*) from sqlite_master where type="table" and name = "{table_name}";' res = con.execute(table_exist_sql) @@ -1424,6 +1550,22 @@ def gen_mem_sample_v3(row) -> MemSample: mem_sample.start_cpu_time *= 10 return mem_sample + + def gen_mem_sample_v4(row) -> MemSample: + tid = row["tid"] + start_time = int(row["time"]) * 10 + cpu_time = int(row["cpu_time"]) * 10 + alloc_size = int(row["alloc_size"]) + alloc_count = int(row["alloc_count"]) + alloc_addr = int(row["alloc_addr"]) + curr_size = int(row["curr_size"]) + stack_id = int(row["stack_id"]) + + mem_sample = MemSample( + tid, curr_size, start_time, cpu_time, stack_id, alloc_size, alloc_count + ) + + return mem_sample mem_sample_sql = ( f"select * from {mem_sample_table_name} where trace_id={trace_id};" @@ -1439,6 +1581,45 @@ def gen_mem_sample_v3(row) -> MemSample: mem_sample = gen_mem_sample_v2(one) elif version == 3: mem_sample = gen_mem_sample_v3(one) + elif version == 4: + mem_sample = gen_mem_sample_v4(one) + else: + raise RuntimeError( + "Unsupported version, please update 'sol' command line tool!" + ) + + tid = mem_sample.tid + tid_trace_list = mem_sample_map.get(tid) or [] + tid_trace_list.append(mem_sample) + mem_sample_map[tid] = tid_trace_list + + if table_exists(con, mem_alloc_sample_table_name): + def gen_mem_alloc_sample_v4(row) -> MemSample: + tid = row["tid"] + start_time = int(row["time"]) * 10 + cpu_time = int(row["cpu_time"]) * 10 + alloc_size = int(row["alloc_size"]) + alloc_count = int(row["alloc_count"]) + alloc_addr = int(row["alloc_addr"]) + # curr_alloc_size = int(row["curr_alloc_size"]) + stack_id = int(row["stack_id"]) + + mem_sample = MemSample( + tid, 0, start_time, cpu_time, stack_id, alloc_size, alloc_count + ) + + return mem_sample + + mem_sample_sql = ( + f"select * from {mem_alloc_sample_table_name} where trace_id={trace_id};" + ) + res = con.execute(mem_sample_sql) + + for one in res.fetchall(): + mem_sample: MemSample + + if version == 4: + mem_sample = gen_mem_alloc_sample_v4(one) else: raise RuntimeError( "Unsupported version, please update 'btrace' command line tool!" @@ -1467,18 +1648,61 @@ def gen_mem_sample_v3(row) -> MemSample: mem_sample_list = gen_mem_sample_list_v2(mem_sample_bytes) elif version == 3: mem_sample_list = gen_mem_sample_list_v3(mem_sample_bytes) + elif version == 4: + mem_sample_list = gen_mem_sample_list_v4(mem_sample_bytes) else: raise RuntimeError( "Unsupported version, please update 'btrace' command line tool!" ) - for mem_sample in mem_sample_list: - alloc_size = int(mem_sample.size) - start_time = mem_sample.start_time - cpu_time = mem_sample.start_cpu_time - stack_id = mem_sample.stack_id - alloc_size = mem_sample.alloc_size - alloc_count = mem_sample.alloc_count + for mem_sample_node in mem_sample_list: + curr_size = int(mem_sample_node.size) + start_time = mem_sample_node.start_time + cpu_time = mem_sample_node.start_cpu_time + stack_id = mem_sample_node.stack_id + alloc_size = mem_sample_node.alloc_size + alloc_count = mem_sample_node.alloc_count + + mem_sample = MemSample( + tid, + curr_size, + start_time, + cpu_time, + stack_id, + alloc_size, + alloc_count, + ) + + tid_trace_list = mem_sample_map.get(tid) or [] + tid_trace_list.append(mem_sample) + mem_sample_map[tid] = tid_trace_list + + if table_exists(con, mem_alloc_batch_sample_table_name): + mem_sample_sql = ( + f"select * from {mem_alloc_batch_sample_table_name} where trace_id={trace_id};" + ) + res = con.execute(mem_sample_sql) + + for one in res.fetchall(): + trace_id = one["trace_id"] + tid = one["tid"] + mem_sample_bytes: bytes = one["nodes"] + mem_sample_list: Optional[List[MemSampleNode]] = None + + if version == 4: + mem_sample_list = gen_mem_alloc_sample_list_v4(mem_sample_bytes) + else: + raise RuntimeError( + "Unsupported version, please update 'sol' command line tool!" + ) + + for mem_sample_node in mem_sample_list: + alloc_size = int(mem_sample_node.size) + start_time = mem_sample_node.start_time + cpu_time = mem_sample_node.start_cpu_time + stack_id = mem_sample_node.stack_id + alloc_size = mem_sample_node.alloc_size + alloc_count = mem_sample_node.alloc_count mem_sample = MemSample( tid, @@ -1506,6 +1730,108 @@ def gen_mem_sample_v3(row) -> MemSample: return mem_sample_map +def read_io_samples( + con: sqlite3.Connection, + trace_id: int, + callstack_table: Dict[int, CallstackNode], + version: int, +) -> Dict[int, List[IOSample]]: + io_sample_map: Dict[int, List[IOSample]] = {} + + if table_exists(con, io_sample_table_name): + def gen_io_sample_v4(row) -> IOSample: + tid = row["tid"] + start_time = int(row["time"]) * 10 + cpu_time = int(row["cpu_time"]) * 10 + alloc_size = int(row["alloc_size"]) + alloc_count = int(row["alloc_count"]) + stack_id = int(row["stack_id"]) + type_size = int(row["type_size"]) + type = (type_size & 0xff) + size = (type_size >> 8) + + io_sample = IOSample( + tid, start_time, cpu_time, stack_id, + alloc_size, alloc_count, type, size + ) + + return io_sample + + io_sample_sql = ( + f"select * from {io_sample_table_name} where trace_id={trace_id};" + ) + res = con.execute(io_sample_sql) + + for one in res.fetchall(): + io_sample: IOSample + + if version == 4: + io_sample = gen_io_sample_v4(one) + else: + raise RuntimeError( + "Unsupported version, please update 'sol' command line tool!" + ) + + tid = io_sample.tid + tid_trace_list = io_sample_map.get(tid) or [] + tid_trace_list.append(io_sample) + io_sample_map[tid] = tid_trace_list + + if table_exists(con, io_batch_sample_table_name): + io_sample_sql = ( + f"select * from {io_batch_sample_table_name} where trace_id={trace_id};" + ) + res = con.execute(io_sample_sql) + + for one in res.fetchall(): + trace_id = one["trace_id"] + tid = one["tid"] + io_sample_bytes: bytes = one["nodes"] + io_sample_list: Optional[List[IOSampleNode]] = None + + if version == 4: + io_sample_list = gen_io_sample_list_v4(io_sample_bytes) + else: + raise RuntimeError( + "Unsupported version, please update 'sol' command line tool!" + ) + + for io_sample_node in io_sample_list: + start_time = io_sample_node.start_time + cpu_time = io_sample_node.start_cpu_time + stack_id = io_sample_node.stack_id + alloc_size = io_sample_node.alloc_size + alloc_count = io_sample_node.alloc_count + type = int(io_sample_node.type) + size = int(io_sample_node.size) + + io_sample = IOSample( + tid, + start_time, + cpu_time, + stack_id, + alloc_size, + alloc_count, + type, + size + ) + + tid_trace_list = io_sample_map.get(tid) or [] + tid_trace_list.append(io_sample) + io_sample_map[tid] = tid_trace_list + + for tid, tid_trace_list in io_sample_map.items(): + for idx, io_sample in enumerate(tid_trace_list): + stack_id = io_sample.stack_id + stack = unwind_stack_from_callstack_table(callstack_table, stack_id) + + if len(stack) == 0 or stack[0] == 0: + continue + + io_sample.calls = stack + + return io_sample_map + def read_async_samples( con: sqlite3.Connection, @@ -1952,6 +2278,8 @@ def read_lock_samples( version: int, ) -> Dict[int, List[LockSample]]: lock_sample_map: Dict[int, List[LockSample]] = {} + lock_contention_map: Dict[int, List[LockContentionPair]] = {} + unlock_contention_list: List[LockSample] = [] if table_exists(con, lock_sample_table_name): # lock sample @@ -2008,17 +2336,17 @@ def read_lock_samples( "Unsupported version, please update 'btrace' command line tool!" ) - for lock_sample in sample_list: - start_time = lock_sample.start_time - cpu_time = lock_sample.start_cpu_time - stack_id = lock_sample.stack_id - alloc_size = lock_sample.alloc_size - alloc_count = lock_sample.alloc_count + for lock_sample_node in sample_list: + start_time = lock_sample_node.start_time + cpu_time = lock_sample_node.start_cpu_time + stack_id = lock_sample_node.stack_id + alloc_size = lock_sample_node.alloc_size + alloc_count = lock_sample_node.alloc_count lock_sample = LockSample( tid, - lock_sample.id, - lock_sample.action, + lock_sample_node.id, + lock_sample_node.action, start_time, cpu_time, stack_id, @@ -2028,10 +2356,41 @@ def read_lock_samples( tid_trace_list = lock_sample_map.get(tid) or [] tid_trace_list.append(lock_sample) lock_sample_map[tid] = tid_trace_list + + lock_contention_set = set([LockAction.kMtxLockContention, + LockAction.kRdlockContention, + LockAction.kWrlockContention, + LockAction.kUnfairLockContention, + LockAction.kCondWaitCtn]) + unlock_contention_set = set([LockAction.kMtxUnlockContention, + LockAction.kRwUnlockContention, + LockAction.kUnfairUnlockContention, + LockAction.kCondSignalCtn, + LockAction.kCondBroadcastCtn]) for tid, tid_trace_list in lock_sample_map.items(): + + tid_trace_list.sort(key=sample_info_key) for idx, lock_sample in enumerate(tid_trace_list): + + # TODO, handle lock_sample lost + action = LockAction(lock_sample.action) + if action in lock_contention_set: + lock_contention_pair_list: List[LockContentionPair] = lock_contention_map.get(lock_sample.id, []) + + if 0 < len(lock_contention_pair_list) and not lock_contention_pair_list[-1].end: + lock_contention_pair_list[-1].end = lock_sample + else: + lock_contention_pair = LockContentionPair(lock_sample.id) + lock_contention_pair.begin = lock_sample + lock_contention_pair_list.append(lock_contention_pair) + + lock_contention_map[lock_sample.id] = lock_contention_pair_list + + elif action in unlock_contention_set: + unlock_contention_list.append(lock_sample) + stack = [] stack_id = lock_sample.stack_id @@ -2041,6 +2400,24 @@ def read_lock_samples( continue lock_sample.calls = stack + + for unlock_contention_sample in unlock_contention_list: + lock_id = unlock_contention_sample.id + lock_contention_pair_list = lock_contention_map.get(lock_id, []) + + for lock_contention_pair in lock_contention_pair_list: + if lock_contention_pair.begin.start_time <= unlock_contention_sample.start_time and \ + unlock_contention_sample.start_time <= lock_contention_pair.end.start_time: + lock_contention_pair.begin.unlock_contention_list.append(unlock_contention_sample) + + # for lock_id, lock_contention_pair_list in lock_contention_map.items(): + # for lock_contention_pair in lock_contention_pair_list: + # # lock_contention_pair.begin.unlock_contention_list = lock_contention_pair.unlock_contention_list + # unlock_contention_list = lock_contention_pair.begin.unlock_contention_list + # if unlock_contention_list: + # print(f"lock: {lock_id}, action: {LockAction(lock_contention_pair.begin.action)}, begin time: {lock_contention_pair.begin.start_time}, end time: {lock_contention_pair.end.start_time}") + # for unlock_contention_sample in unlock_contention_list: + # print(f"\tunlock contention, tid: {unlock_contention_sample.tid}, lock: {lock_id}, action: {LockAction(unlock_contention_sample.action)}, time: {unlock_contention_sample.start_time}") return lock_sample_map @@ -2085,9 +2462,10 @@ def read_thread_info( def read_custome_perfetto_info( - con: sqlite3.Connection, trace_id: int, version: int + con: sqlite3.Connection, trace_id: int, version: int, trace_start_time: int ) -> Tuple[Dict[str, List], Dict[str, List[PerfettoCounterInfo]]]: slice_info_map: Dict[str, List] = {} + slice_info_v2_map: Dict[str, List] = {} counter_info_map: Dict[str, List[PerfettoCounterInfo]] = {} if not table_exists(con, timeseries_info_table_name): @@ -2132,6 +2510,36 @@ def read_custome_perfetto_info( slice_info_list = slice_info_map.get(type) or [] slice_info_list.append(slice_info) slice_info_map[type] = slice_info_list + elif perfetto_type == "slice_v2": + begin_time = int(info["begin_time"]) + end_time = int(info["end_time"]) + name = info.get("name", "") + debug_info = info.get("debug_info", {}) + + if end_time < begin_time: + continue + + slice_info = PerfettoSliceInfo(type, begin_time, end_time, name, debug_info) + slice_info_list = slice_info_v2_map.get(type) or [] + slice_info_list.append(slice_info) + slice_info_v2_map[type] = slice_info_list + + slice_info_map.update(slice_info_v2_map) + + def slice_info_key(slice_info: PerfettoSliceInfo): + return slice_info.begin_time + + for _, slice_info_list in slice_info_v2_map.items(): + slice_info_list.sort(key=slice_info_key) + + for item in slice_info_list: + item: PerfettoSliceInfo = item + item.begin_time -= trace_start_time + item.end_time -= trace_start_time + if item.begin_time < 0: + item.begin_time = 0 + if item.end_time < 0: + item.end_time = 0 return slice_info_map, counter_info_map @@ -2181,9 +2589,9 @@ def read_file(path: str) -> TraceRawContent: callstack_table = read_callstack_table(con, trace_id, version) thread_info_map = read_thread_info(con, trace_id, version) slice_info_map, counter_info_map = read_custome_perfetto_info( - con, trace_id, version + con, trace_id, version, trace_start_time ) - + cpu_sample_map = read_cpu_samples(con, trace_id, callstack_table, version) mem_sample_map = read_mem_samples(con, trace_id, callstack_table, version) async_sample_map = read_async_samples(con, trace_id, callstack_table, version) @@ -2192,6 +2600,7 @@ def read_file(path: str) -> TraceRawContent: lock_sample_map = read_lock_samples(con, trace_id, callstack_table, version) profile_sample_map = read_profile_samples(con, trace_id, callstack_table, version) time_range_sample_map = read_time_range_samples(con, trace_id, callstack_table, version) + io_sample_map = read_io_samples(con, trace_id, callstack_table, version) total_cpu_sample_list: List[CPUSample] = [] sample_map: Dict[int, List[CPUSample]] = {} @@ -2235,6 +2644,24 @@ def read_file(path: str) -> TraceRawContent: cpu_sample.type = "mem" sample_list.append(cpu_sample) sample_map[tid] = sample_list + + for tid, io_sample_list in io_sample_map.items(): + sample_list = sample_map.get(tid, []) + for io_sample in io_sample_list: + cpu_sample = CPUSample( + io_sample.tid, + io_sample.start_time, + io_sample.start_time, + io_sample.start_cpu_time, + io_sample.start_cpu_time, + io_sample.stack_id, + io_sample.alloc_size, + io_sample.alloc_count, + io_sample.calls, + ) + cpu_sample.type = "mem" + sample_list.append(cpu_sample) + sample_map[tid] = sample_list for tid, async_sample_list in async_sample_map.items(): sample_list = sample_map.get(tid, []) @@ -2287,6 +2714,10 @@ def read_file(path: str) -> TraceRawContent: lock_sample.calls, ) cpu_sample.type = "lock" + + if lock_sample.unlock_contention_list: + cpu_sample.unlock_contention_list = lock_sample.unlock_contention_list + sample_list.append(cpu_sample) sample_map[tid] = sample_list @@ -2343,7 +2774,7 @@ def read_file(path: str) -> TraceRawContent: val: CPUSample = thread_cpu_sample_map.values()[idx - 1] if start_time == timestamp: - diff_cpu_time = sample.start_cpu_time - val.start_cpu_time + diff_cpu_time = max(sample.start_cpu_time - val.start_cpu_time, 100) sample.start_time += diff_cpu_time sample.end_time += diff_cpu_time timestamp = sample.start_time diff --git a/btrace-iOS/BTraceTool/btrace/model.py b/btrace-iOS/BTraceTool/btrace/model.py index 349f65c..ff39b31 100644 --- a/btrace-iOS/BTraceTool/btrace/model.py +++ b/btrace-iOS/BTraceTool/btrace/model.py @@ -11,7 +11,7 @@ # See the License for the specific language governing permissions and # limitations under the License. -from typing import Dict, List +from typing import Dict, List, Optional from enum import Enum @@ -72,10 +72,12 @@ def __init__(self, type: str, time: int, val: int): class PerfettoSliceInfo: - def __init__(self, type: str, begin_time: int, end_time: int): + def __init__(self, type: str, begin_time: int, end_time: int, name: str="", debug_info: Dict={}): self.type = type + self.name = name self.begin_time = begin_time self.end_time = end_time + self.debug_info = debug_info class AsyncSampleNode: @@ -193,6 +195,9 @@ class LockAction(Enum): kUnfairTrylock = 20 kUnfairLockContention = 21 kUnfairUnlockContention = 22 + kCondWaitCtn = 23 + kCondSignalCtn = 24 + kCondBroadcastCtn = 25 class LockSampleNode: @@ -239,6 +244,15 @@ def __init__( self.calls: List[int] = [] self.alloc_size = alloc_size self.alloc_count = alloc_count + self.unlock_contention_list: List[LockSample] = [] + +class LockContentionPair: + + def __init__(self, id: int): + self.id = id + self.begin: LockSample = None + self.end: LockSample = None + self.unlock_contention_list: List[LockSample] = [] class DateSample: @@ -273,6 +287,51 @@ def __init__( self.alloc_size = alloc_size self.alloc_count = alloc_count +class IOSample: + + def __init__( + self, + tid: int, + time: int, + cpu_time: int, + stack_id: int, + alloc_size: int, + alloc_count: int, + type: int, + size: int + ): + self.type = "io" + self.tid = tid + self.start_time = time + self.start_cpu_time = cpu_time + self.stack_id = stack_id + self.calls: List[int] = [] + self.alloc_size = alloc_size + self.alloc_count = alloc_count + self.type = type + self.size = size + + +class IOSampleNode: + + def __init__( + self, + time: int, + cpu_time: int, + stack_id: int, + alloc_size: int, + alloc_count: int, + type: int, + size: int + ): + self.start_time = time + self.start_cpu_time = cpu_time + self.stack_id = stack_id + self.alloc_size = alloc_size + self.alloc_count = alloc_count + self.type = type + self.size = size + class MemSample: @@ -342,6 +401,7 @@ def __init__( self.alloc_size = alloc_size self.alloc_count = alloc_count self.calls: List[int] = calls + self.unlock_contention_list: List[LockSample] = [] class IntervalSampleNode: @@ -496,6 +556,7 @@ def __init__( self.alloc_count = end_alloc_count - start_alloc_count self.children: List[MethodNode] = [] self.parent: MethodNode = None + self.unlock_contention_list: List[LockSample] = [] def update_cpu_time(self, cpu_time): if self.end_cpu_time < cpu_time: diff --git a/btrace-iOS/BTraceTool/btrace/parse.py b/btrace-iOS/BTraceTool/btrace/parse.py index 644de5a..8c654b1 100644 --- a/btrace-iOS/BTraceTool/btrace/parse.py +++ b/btrace-iOS/BTraceTool/btrace/parse.py @@ -13,6 +13,7 @@ import bisect import os +import subprocess from typing import Dict, List, Set, Optional, Tuple from btrace import symbol_info from btrace.extractor import read_file @@ -28,6 +29,7 @@ ) from btrace.open_trace import open_trace from btrace.pb import perfetto_pb2 +from btrace import util from btrace.perfetto import gen_perfetto_trace @@ -79,6 +81,37 @@ def symbolicate( image_dsym_path_map, image_info, address_list, addr_symbol_map ) + cpp_demangle_info_list: List[SymbolInfo] = [] + cpp_demangle_name_list: List[str] = [] + for _, info in addr_symbol_map.items(): + if info.name.startswith("_Z") and info.name.find("metasec") == -1 and \ + info.name.find("[") == -1: + cpp_demangle_info_list.append(info) + cpp_demangle_name_list.append(f"_{info.name}") + + if len(cpp_demangle_name_list): + batch = 0 + batch_size = 100 + while True: + begin_idx = batch * batch_size + + if len(cpp_demangle_name_list) <= begin_idx: + break + + end_idx = min((batch+1) * batch_size, len(cpp_demangle_name_list)) + cpp_name_list = " ".join(cpp_demangle_name_list[begin_idx:end_idx]) + cmd_str = f"c++filt {cpp_name_list}" + demangle_name_list: List[str] = subprocess.run(cmd_str, shell=True, capture_output=True).stdout.decode().strip().split("\n") + + if len(demangle_name_list) == end_idx - begin_idx: + for i in range(begin_idx, end_idx): + info = cpp_demangle_info_list[i] + demangle_name = demangle_name_list[i-begin_idx] + if demangle_name: + info.name = demangle_name + + batch += 1 + return addr_symbol_map @@ -97,7 +130,7 @@ def beautify_method_tree(root: MethodNode): next_time = next_node.start_time diff_time = next_time - node.end_time - node.end_time = node.end_time + int(min(diff_time, 1000)) # 1000us + node.end_time = node.end_time + int(min(diff_time, 100)) # 1000us child_wall_time = node.end_time - node.start_time if child_wall_time <= 0: @@ -134,7 +167,8 @@ def construct_method_tree( alloc_size = sample.alloc_size alloc_count = sample.alloc_count stack = sample.calls - + unlock_contention_list = sample.unlock_contention_list + if idx == 0: parent_node = method_tree.root @@ -151,6 +185,10 @@ def construct_method_tree( alloc_count, alloc_count, ) + + if unlock_contention_list and i == len(stack)-1: + node.unlock_contention_list = unlock_contention_list + method_tree.put_child(node, parent_node) parent_node = node else: @@ -177,6 +215,9 @@ def construct_method_tree( last_child.update_end_time(end_time) last_child.update_alloc_size(alloc_size) last_child.update_alloc_count(alloc_count) + + if unlock_contention_list and j == len(stack)-1: + last_child.unlock_contention_list = unlock_contention_list parent_node = last_child i += 1 @@ -196,6 +237,10 @@ def construct_method_tree( prev_sample.alloc_count, alloc_count, ) + + if unlock_contention_list and j == len(stack)-1: + node.unlock_contention_list = unlock_contention_list + method_tree.put_child(node, parent_node) parent_node = node j += 1 @@ -222,11 +267,11 @@ def parse_raw_data( cpu_sample_list = raw_content.cpu_sample_list image_info_list = raw_content.image_info_list - image_info_map: Dict[ImageInfo] = {} + image_info_map: Dict[str, ImageInfo] = {} image_addr_set_map: Dict[str, Set[int]] = {} image_address_list = [image_info.address for image_info in image_info_list] - for sample in cpu_sample_list: + for sample in cpu_sample_list: for address in sample.calls: image_info_idx = get_image_info(image_address_list, address) @@ -270,7 +315,7 @@ def parse_raw_data( for address in sample.calls: symbol_info = addr_symbol_map.get(address) - + if symbol_info: stack.append(address) @@ -303,12 +348,13 @@ def parse_raw_data( def parse( - file_path: str, dsym_path: str, force: bool = False, sys_symbol: bool = False + file_path: str, dsym_path: str, force: bool = False, sys_symbol: bool = False, + upload: bool = False ): print("parsing file, please wait...") if not os.path.exists(dsym_path): - err_msg = "Dsym path does not exist!" + err_msg = f"Dsym path {dsym_path} does not exist!" raise RuntimeError(err_msg) file_prefix, file_ext = os.path.splitext(file_path) @@ -338,4 +384,4 @@ def parse( trace_bytes = trace_pb.SerializeToString() fp.write(trace_bytes) - open_trace(output_path) + open_trace(output_path) \ No newline at end of file diff --git a/btrace-iOS/BTraceTool/btrace/perfetto.py b/btrace-iOS/BTraceTool/btrace/perfetto.py index 6930117..3887760 100644 --- a/btrace-iOS/BTraceTool/btrace/perfetto.py +++ b/btrace-iOS/BTraceTool/btrace/perfetto.py @@ -152,6 +152,13 @@ def method_tree_to_trace(trace_packet_list: List[perfetto_pb2.TracePacket], thre "alloc_size": alloc_size, "alloc_count": alloc_count } + + if method_node.unlock_contention_list: + contention_tids = [str(x.tid) for x in method_node.unlock_contention_list] + debug_infos["locked_by"] = ", ".join(contention_tids) + debug_infos["lock_id"] = str(method_node.unlock_contention_list[0].id) + symbol_name = symbol_name + "(lock_contention)" + start_packet = gen_slice_event_packet(thread_track.uuid, start_time, symbol_name, perfetto_pb2.TrackEvent.Type.TYPE_SLICE_BEGIN, debug_infos) trace_packet_list.append(start_packet) @@ -195,15 +202,22 @@ def gen_perfetto_trace(method_tree_list: List[MethodTree], counter_event = gen_counter_event_packet(counter_track.uuid, time, val) trace_packet_list.append(counter_event) - for slice_name, v in slice_info_map.items(): + for slice_type, v in slice_info_map.items(): slice_info_list: List[PerfettoSliceInfo] = v - slice_packet = gen_sub_packet(auto_increase.get(), root_uuid, f"{slice_name}") + slice_packet = gen_sub_packet(auto_increase.get(), root_uuid, f"{slice_type}") trace_packet_list.append(slice_packet) for slice_info in slice_info_list: + slice_name: str = "" + if len(slice_info.name): + slice_name = slice_info.name + else: + slice_name = slice_type + + debug_info = slice_info.debug_info slice_track = slice_packet.track_descriptor begin_time = slice_info.begin_time * 1000 - start_packet = gen_slice_event_packet(slice_track.uuid, begin_time, slice_name, perfetto_pb2.TrackEvent.Type.TYPE_SLICE_BEGIN) + start_packet = gen_slice_event_packet(slice_track.uuid, begin_time, slice_name, perfetto_pb2.TrackEvent.Type.TYPE_SLICE_BEGIN, debug_info) trace_packet_list.append(start_packet) end_time = slice_info.end_time * 1000 end_packet = gen_slice_event_packet(slice_track.uuid, end_time, slice_name, perfetto_pb2.TrackEvent.Type.TYPE_SLICE_END) diff --git a/btrace-iOS/BTraceTool/btrace/util.py b/btrace-iOS/BTraceTool/btrace/util.py index 33b6456..67ad36f 100644 --- a/btrace-iOS/BTraceTool/btrace/util.py +++ b/btrace-iOS/BTraceTool/btrace/util.py @@ -11,45 +11,86 @@ # See the License for the specific language governing permissions and # limitations under the License. +import gzip +import json import os import sys import signal import subprocess from typing import Dict, List, Optional, Union +import requests + SRC_PORT = 11288 DST_PORT = 1128 API_HOST = "http://localhost:" + str(SRC_PORT) BTRACE_ROOT_DIR = os.path.dirname(os.path.abspath(__file__)) -TIMESERIES_CONFIG = {} +TIMESERIES_CONFIG = {"mem_usage": True, "cpu_usage": True} TIMEPROFILER_CONFIG = {"period": 1, "bg_period": 2, "active_only": False, "merge_stack": False} MEMPROFILER_CONFIG = {"lite_mode": 0, "interval": 10, "period": 1, "bg_period": 2} DATEPROFILER_CONFIG = {"period": 1, "bg_period": 2} DISPATCHPROFILER_CONFIG = {"period": 1, "bg_period": 2} LOCKPROFILER_CONFIG = {"period": 1, "bg_period": 2} +IOPROFILER_CONFIG = {"period": 1, "bg_period": 2} DEFAULT_CONFIG = { "enable": True, "timeout": 36000, "max_records": 10000, + "dump_queue_name": True, "plugins": [ {"name": "timeseries", "config": TIMESERIES_CONFIG}, {"name": "timeprofiler", "config": TIMEPROFILER_CONFIG}, {"name": "memoryprofiler", "config": MEMPROFILER_CONFIG}, {"name": "dateprofiler", "config": DATEPROFILER_CONFIG}, - {"name": "dispatchprofiler", "config": DISPATCHPROFILER_CONFIG}, - {"name": "lockprofiler", "config": LOCKPROFILER_CONFIG} + # {"name": "dispatchprofiler", "config": DISPATCHPROFILER_CONFIG}, + {"name": "lockprofiler", "config": LOCKPROFILER_CONFIG}, + # {"name": "ioprofiler", "config": IOPROFILER_CONFIG} ] } VERBOSE = False -def set_record_parameter(main_only=False, hitch_thres=50): +def set_record_parameter(main_only=False, hitch_thres=50, frequency: str=""): plugins: List[Dict] = DEFAULT_CONFIG["plugins"] - + + high_freq = False + frequency_num = 1 + + if frequency: + try: + frequency = frequency.strip() + frequency_num = int(frequency) + except: + if frequency.endswith("ms"): + frequency_num = int(frequency[:-2]) + frequency_num = max(frequency_num, 1) + elif frequency.endswith("us"): + high_freq = True + frequency_num = int(frequency[:-2]) + frequency_num = max(frequency_num, 100) + else: + raise RuntimeError("Only accept 'ms' or 'us'") + DEFAULT_CONFIG["main_only"] = main_only + DEFAULT_CONFIG["high_freq"] = high_freq + + if high_freq: + MEMPROFILER_CONFIG["interval"] = 3 + + if 1 != frequency_num: + TIMEPROFILER_CONFIG["period"] = frequency_num + TIMEPROFILER_CONFIG["bg_period"] = 2 * frequency_num + MEMPROFILER_CONFIG["period"] = frequency_num + MEMPROFILER_CONFIG["bg_period"] = 2 * frequency_num + DATEPROFILER_CONFIG["period"] = frequency_num + DATEPROFILER_CONFIG["bg_period"] = 2 * frequency_num + DISPATCHPROFILER_CONFIG["period"] = frequency_num + DISPATCHPROFILER_CONFIG["bg_period"] = 2 * frequency_num + LOCKPROFILER_CONFIG["period"] = frequency_num + LOCKPROFILER_CONFIG["bg_period"] = 2 * frequency_num if main_only: TIMEPROFILER_CONFIG["bg_period"] = 10_000_000 @@ -58,7 +99,7 @@ def set_record_parameter(main_only=False, hitch_thres=50): DISPATCHPROFILER_CONFIG["bg_period"] = 10_000_000 LOCKPROFILER_CONFIG["bg_period"] = 10_000_000 - MONITOR_CONFIG = {"hang": {"config": {"hitch": hitch_thres}}} + MONITOR_CONFIG = {"hang": {"config": {"hitch": hitch_thres, "perfetto": True}}} MONITOR_PLUGIN = {"name": "monitor", "config": MONITOR_CONFIG} plugins.append(MONITOR_PLUGIN) @@ -116,39 +157,43 @@ def clean_subprocess(pid_list: List[int]): kill_process(pid) -def macho_uuid(file_path) -> Optional[str]: +def macho_uuid(file_path: str) -> Optional[str]: uuid = "" from macholib import MachO, mach_o import lief + if not lief.is_macho(file_path): return uuid - - # fat_bin = lief.MachO.parse(file_path) - - # if not fat_bin: - # return uuid - # arm64_bin: Optional[lief.MachO.Binary] = None + try: + for cmd in MachO.MachO(file_path).headers[0].commands: + if cmd[0].cmd == mach_o.LC_UUID: + uudi_bytes = cmd[1].uuid + uuid = "".join([f'{i:02x}' for i in uudi_bytes]) + break + except Exception as e: + config = lief.MachO.ParserConfig().quick + fat_bin = lief.MachO.parse(file_path, config) - # for i in range(fat_bin.size): - # macho_bin = fat_bin.at(i) - # if macho_bin.header.cpu_type == lief.MachO.Header.CPU_TYPE.ARM64: - # arm64_bin = macho_bin - # break + if not fat_bin: + return uuid - # if not arm64_bin: - # return uuid + arm64_bin: Optional[lief.MachO.Binary] = None - # if arm64_bin.has_uuid: - # uuid_list: List[int] = arm64_bin.uuid.uuid - # uuid = "".join([f'{i:x}' for i in uuid_list]) - - for cmd in MachO.MachO(file_path).headers[0].commands: - if cmd[0].cmd == mach_o.LC_UUID: - uudi_bytes = cmd[1].uuid - uuid = "".join([f'{i:02x}' for i in uudi_bytes]) - break + for i in range(fat_bin.size): + macho_bin = fat_bin.at(i) + if macho_bin.header.cpu_type == lief.MachO.Header.CPU_TYPE.ARM64: + arm64_bin = macho_bin + break + + if not arm64_bin: + return uuid + + if arm64_bin.has_uuid: + uuid_list: List[int] = arm64_bin.uuid.uuid + uuid = "".join([f'{i:02x}' for i in uuid_list]) + return uuid @@ -174,9 +219,3 @@ def verbose() -> bool: def curr_interpreter() -> str: return sys.executable - - -if __name__ == "__main__": - prt(DEFAULT_CONFIG, ANSI.BG_BLUE) - set_record_parameter() - prt(DEFAULT_CONFIG, ANSI.RED) diff --git a/btrace-iOS/BTraceTool/pyproject.toml b/btrace-iOS/BTraceTool/pyproject.toml index 793f8b3..d79dd26 100644 --- a/btrace-iOS/BTraceTool/pyproject.toml +++ b/btrace-iOS/BTraceTool/pyproject.toml @@ -1,6 +1,6 @@ [tool.poetry] name = "btrace" -version = "0.8.1" +version = "0.9.2" description = "" authors = ["bytedance"] readme = "README.md"