latency_logger.py 9.4 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242
  1. #!/usr/bin/env python3
  2. import argparse
  3. import json
  4. import matplotlib.patches as mpatches
  5. import matplotlib.pyplot as plt
  6. import mpld3
  7. import sys
  8. from bisect import bisect_left, bisect_right
  9. from collections import defaultdict
  10. from openpilot.tools.lib.logreader import LogReader
  11. DEMO_ROUTE = "9f583b1d93915c31|2022-05-18--10-49-51--0"
  12. SERVICES = ['camerad', 'modeld', 'plannerd', 'controlsd', 'boardd']
  13. MONOTIME_KEYS = ['modelMonoTime', 'lateralPlanMonoTime']
  14. MSGQ_TO_SERVICE = {
  15. 'roadCameraState': 'camerad',
  16. 'wideRoadCameraState': 'camerad',
  17. 'modelV2': 'modeld',
  18. 'longitudinalPlan': 'plannerd',
  19. 'sendcan': 'controlsd',
  20. 'controlsState': 'controlsd'
  21. }
  22. SERVICE_TO_DURATIONS = {
  23. 'camerad': ['processingTime'],
  24. 'modeld': ['modelExecutionTime', 'gpuExecutionTime'],
  25. 'plannerd': ['solverExecutionTime'],
  26. }
  27. def read_logs(lr):
  28. data = defaultdict(lambda: defaultdict(lambda: defaultdict(list)))
  29. mono_to_frame = {}
  30. frame_mismatches = []
  31. frame_id_fails = 0
  32. latest_sendcan_monotime = 0
  33. for msg in lr:
  34. if msg.which() == 'sendcan':
  35. latest_sendcan_monotime = msg.logMonoTime
  36. continue
  37. if msg.which() in MSGQ_TO_SERVICE:
  38. service = MSGQ_TO_SERVICE[msg.which()]
  39. msg_obj = getattr(msg, msg.which())
  40. frame_id = -1
  41. if hasattr(msg_obj, "frameId"):
  42. frame_id = msg_obj.frameId
  43. else:
  44. continue_outer = False
  45. for key in MONOTIME_KEYS:
  46. if hasattr(msg_obj, key):
  47. if getattr(msg_obj, key) == 0:
  48. # Filter out controlsd messages which arrive before the camera loop
  49. continue_outer = True
  50. elif getattr(msg_obj, key) in mono_to_frame:
  51. frame_id = mono_to_frame[getattr(msg_obj, key)]
  52. if continue_outer:
  53. continue
  54. if frame_id == -1:
  55. frame_id_fails += 1
  56. continue
  57. mono_to_frame[msg.logMonoTime] = frame_id
  58. data['timestamp'][frame_id][service].append((msg.which()+" published", msg.logMonoTime))
  59. next_service = SERVICES[SERVICES.index(service)+1]
  60. if not data['start'][frame_id][next_service]:
  61. data['start'][frame_id][next_service] = msg.logMonoTime
  62. data['end'][frame_id][service] = msg.logMonoTime
  63. if service in SERVICE_TO_DURATIONS:
  64. for duration in SERVICE_TO_DURATIONS[service]:
  65. data['duration'][frame_id][service].append((msg.which()+"."+duration, getattr(msg_obj, duration)))
  66. if service == SERVICES[0]:
  67. data['timestamp'][frame_id][service].append((msg.which()+" start of frame", msg_obj.timestampSof))
  68. if not data['start'][frame_id][service]:
  69. data['start'][frame_id][service] = msg_obj.timestampSof
  70. elif msg.which() == 'controlsState':
  71. # Sendcan is published before controlsState, but the frameId is retrieved in CS
  72. data['timestamp'][frame_id][service].append(("sendcan published", latest_sendcan_monotime))
  73. elif msg.which() == 'modelV2':
  74. if msg_obj.frameIdExtra != frame_id:
  75. frame_mismatches.append(frame_id)
  76. if frame_id_fails > 20:
  77. print("Warning, many frameId fetch fails", frame_id_fails)
  78. if len(frame_mismatches) > 20:
  79. print("Warning, many frame mismatches", len(frame_mismatches))
  80. return (data, frame_mismatches)
  81. # This is not needed in 3.10 as a "key" parameter is added to bisect
  82. class KeyifyList:
  83. def __init__(self, inner, key):
  84. self.inner = inner
  85. self.key = key
  86. def __len__(self):
  87. return len(self.inner)
  88. def __getitem__(self, k):
  89. return self.key(self.inner[k])
  90. def find_frame_id(time, service, start_times, end_times):
  91. left = bisect_left(KeyifyList(list(start_times.items()),
  92. lambda x: x[1][service] if x[1][service] else -1), time) - 1
  93. right = bisect_right(KeyifyList(list(end_times.items()),
  94. lambda x: x[1][service] if x[1][service] else float("inf")), time)
  95. return left, right
  96. def find_t0(start_times, frame_id=-1):
  97. frame_id = frame_id if frame_id > -1 else min(start_times.keys())
  98. m = max(start_times.keys())
  99. while frame_id <= m:
  100. for service in SERVICES:
  101. if start_times[frame_id][service]:
  102. return start_times[frame_id][service]
  103. frame_id += 1
  104. raise Exception('No start time has been set')
  105. def insert_cloudlogs(lr, timestamps, start_times, end_times):
  106. # at least one cloudlog must be made in controlsd
  107. t0 = find_t0(start_times)
  108. failed_inserts = 0
  109. latest_controls_frameid = 0
  110. for msg in lr:
  111. if msg.which() == "logMessage":
  112. jmsg = json.loads(msg.logMessage)
  113. if "timestamp" in jmsg['msg']:
  114. time = int(jmsg['msg']['timestamp']['time'])
  115. service = jmsg['ctx']['daemon']
  116. event = jmsg['msg']['timestamp']['event']
  117. if time < t0:
  118. # Filter out controlsd messages which arrive before the camera loop
  119. continue
  120. if "frame_id" in jmsg['msg']['timestamp']:
  121. timestamps[int(jmsg['msg']['timestamp']['frame_id'])][service].append((event, time))
  122. continue
  123. if service == "boardd":
  124. timestamps[latest_controls_frameid][service].append((event, time))
  125. end_times[latest_controls_frameid][service] = time
  126. else:
  127. frame_id = find_frame_id(time, service, start_times, end_times)
  128. if frame_id:
  129. if frame_id[0] != frame_id[1]:
  130. event += " (warning: ambiguity)"
  131. frame_id = frame_id[0]
  132. if service == 'controlsd':
  133. latest_controls_frameid = frame_id
  134. timestamps[frame_id][service].append((event, time))
  135. else:
  136. failed_inserts += 1
  137. if latest_controls_frameid == 0:
  138. print("Warning: failed to bind boardd logs to a frame ID. Add a timestamp cloudlog in controlsd.")
  139. elif failed_inserts > len(timestamps):
  140. print(f"Warning: failed to bind {failed_inserts} cloudlog timestamps to a frame ID")
  141. def print_timestamps(timestamps, durations, start_times, relative):
  142. t0 = find_t0(start_times)
  143. for frame_id in timestamps.keys():
  144. print('='*80)
  145. print("Frame ID:", frame_id)
  146. if relative:
  147. t0 = find_t0(start_times, frame_id)
  148. for service in SERVICES:
  149. print(" "+service)
  150. events = timestamps[frame_id][service]
  151. for event, time in sorted(events, key = lambda x: x[1]):
  152. print(" "+'%-53s%-53s' %(event, str((time-t0)/1e6)))
  153. for event, time in durations[frame_id][service]:
  154. print(" "+'%-53s%-53s' %(event, str(time*1000)))
  155. def graph_timestamps(timestamps, start_times, end_times, relative, offset_services=False, title=""):
  156. # mpld3 doesn't convert properly to D3 font sizes
  157. plt.rcParams.update({'font.size': 18})
  158. t0 = find_t0(start_times)
  159. fig, ax = plt.subplots()
  160. ax.set_xlim(0, 130 if relative else 750)
  161. ax.set_ylim(0, 17)
  162. ax.set_xlabel('Time (milliseconds)')
  163. colors = ['blue', 'green', 'red', 'yellow', 'purple']
  164. offsets = [[0, -5*j] for j in range(len(SERVICES))] if offset_services else None
  165. height = 0.3 if offset_services else 0.9
  166. assert len(colors) == len(SERVICES), 'Each service needs a color'
  167. points = {"x": [], "y": [], "labels": []}
  168. for i, (frame_id, services) in enumerate(timestamps.items()):
  169. if relative:
  170. t0 = find_t0(start_times, frame_id)
  171. service_bars = []
  172. for service, events in services.items():
  173. if start_times[frame_id][service] and end_times[frame_id][service]:
  174. start = start_times[frame_id][service]
  175. end = end_times[frame_id][service]
  176. service_bars.append(((start-t0)/1e6,(end-start)/1e6))
  177. for event in events:
  178. points['x'].append((event[1]-t0)/1e6)
  179. points['y'].append(i)
  180. points['labels'].append(event[0])
  181. ax.broken_barh(service_bars, (i-height/2, height), facecolors=(colors), alpha=0.5, offsets=offsets)
  182. scatter = ax.scatter(points['x'], points['y'], marker='d', edgecolor='black')
  183. tooltip = mpld3.plugins.PointLabelTooltip(scatter, labels=points['labels'])
  184. mpld3.plugins.connect(fig, tooltip)
  185. plt.title(title)
  186. # Set size relative window size is not trivial: https://github.com/mpld3/mpld3/issues/65
  187. fig.set_size_inches(18, 9)
  188. plt.legend(handles=[mpatches.Patch(color=colors[i], label=SERVICES[i]) for i in range(len(SERVICES))])
  189. return fig
  190. def get_timestamps(lr):
  191. lr = list(lr)
  192. data, frame_mismatches = read_logs(lr)
  193. insert_cloudlogs(lr, data['timestamp'], data['start'], data['end'])
  194. return data, frame_mismatches
  195. if __name__ == "__main__":
  196. parser = argparse.ArgumentParser(description="A tool for analyzing openpilot's end-to-end latency",
  197. formatter_class = argparse.ArgumentDefaultsHelpFormatter)
  198. parser.add_argument("--relative", action="store_true", help="Make timestamps relative to the start of each frame")
  199. parser.add_argument("--demo", action="store_true", help="Use the demo route instead of providing one")
  200. parser.add_argument("--plot", action="store_true", help="If a plot should be generated")
  201. parser.add_argument("--offset", action="store_true", help="Vertically offset service to better visualize overlap")
  202. parser.add_argument("route_or_segment_name", nargs='?', help="The route to print")
  203. if len(sys.argv) == 1:
  204. parser.print_help()
  205. sys.exit()
  206. args = parser.parse_args()
  207. r = DEMO_ROUTE if args.demo else args.route_or_segment_name.strip()
  208. lr = LogReader(r, sort_by_time=True)
  209. data, _ = get_timestamps(lr)
  210. print_timestamps(data['timestamp'], data['duration'], data['start'], args.relative)
  211. if args.plot:
  212. mpld3.show(graph_timestamps(data['timestamp'], data['start'], data['end'], args.relative, offset_services=args.offset, title=r))