sadmen
/
openpilot_comma
mirror of https://github.com/commaai/openpilot.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

latency logger: add offset to visualize overlap (#24644)

Browse Source 
* plot design

* readme

* y label

* readme img

* bigger gaps

* readme figs

* denser lines

* denser lines

* offset flag

* readme

* cleanup

* Update tools/latencylogger/latency_logger.py

* Update tools/latencylogger/latency_logger.py

Co-authored-by: Adeeb Shihadeh <adeebshihadeh@gmail.com>
pull/24662/head
Lukas Petersson 3 years ago committed by GitHub
parent dff70876c3
commit cc4107fd1f
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 63 additions and 64 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Unified View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 111
      tools/latencylogger/README.md
  2. 16
      tools/latencylogger/latency_logger.py

111
tools/latencylogger/README.md
Unescape View File

@ -19,77 +19,74 @@ optional arguments:
--relative Make timestamps relative to the start of each frame (default: False) --relative Make timestamps relative to the start of each frame (default: False)
--demo Use the demo route instead of providing one (default: False) --demo Use the demo route instead of providing one (default: False)
--plot If a plot should be generated (default: False) --plot If a plot should be generated (default: False)
--offset Offset service to better visualize overlap (default: False)
``` ```
To timestamp an event, use `LOGT("msg")` in c++ code or `cloudlog.timestamp("msg")` in python code. If the print is warning for frameId assignment ambiguity, use `LOGT(frameId ,"msg")`. To timestamp an event, use `LOGT("msg")` in c++ code or `cloudlog.timestamp("msg")` in python code. If the print is warning for frameId assignment ambiguity, use `LOGT(frameId ,"msg")`.
## Examples ## Examples
Plotting with relative starts each process at time=0 and gives a nice overview. Timestamps are visualized as diamonds. The opacity allows for visualization of overlapping services.
![relplot-1](https://user-images.githubusercontent.com/42323981/162108651-e0beee14-56e4-466d-8af1-cb37129fd94a.png)
Plotting without relative provides info about the frames relative time. Timestamps are visualized as diamonds
![plot-1](https://user-images.githubusercontent.com/42323981/162108694-fbfe907b-a1ee-4cc7-bc8b-162a7d9305d4.png)
| | Relative | Absolute |
| ------------- | ------------- | ------------- |
| Inline | ![inrel](https://user-images.githubusercontent.com/42323981/170559939-465df3b1-bf87-46d5-b5ee-5cc87dc49470.png) | ![inabs](https://user-images.githubusercontent.com/42323981/170559985-a82f87e7-82c4-4e48-a348-4221568dd589.png) |
| Offset | ![offrel](https://user-images.githubusercontent.com/42323981/170559854-93fba90f-acc4-4d08-b317-d3f8fc649ea8.png) | ![offabs](https://user-images.githubusercontent.com/42323981/170559782-06ed5599-d4e3-4701-ad78-5c1eec6cb61e.png) |
Printed timestamps of a frame with internal durations. Printed timestamps of a frame with internal durations.
``` ```
Frame ID: 371 Frame ID: 1202
camerad camerad
wideRoadCameraState start of frame 0.0 wideRoadCameraState start of frame 0.0
roadCameraState start of frame 0.072395 roadCameraState start of frame 0.049583
wideRoadCameraState published 47.804745 wideRoadCameraState published 35.01206
WideRoadCamera: Image set 47.839849 WideRoadCamera: Image set 35.020028
roadCameraState published 48.319166 roadCameraState published 38.508261
RoadCamera: Image set 48.354478 RoadCamera: Image set 38.520344
RoadCamera: Transformed 48.430258 RoadCamera: Transformed 38.616176
wideRoadCameraState.processingTime 16.733376309275627 wideRoadCameraState.processingTime 3.152403049170971
roadCameraState.processingTime 16.218071803450584 roadCameraState.processingTime 6.453451234847307
modeld modeld
Image added 51.346522 Image added 40.909841
Extra image added 53.179467 Extra image added 42.515027
Execution finished 71.584437 Execution finished 63.002552
modelV2 published 71.76881 modelV2 published 63.148747
modelV2.modelExecutionTime 22.54236489534378 modelV2.modelExecutionTime 23.62649142742157
modelV2.gpuExecutionTime 0.0 modelV2.gpuExecutionTime 0.0
plannerd plannerd
lateralPlan published 77.381862 lateralPlan published 66.915049
longitudinalPlan published 84.207972 longitudinalPlan published 69.715999
lateralPlan.solverExecutionTime 1.3547739945352077 lateralPlan.solverExecutionTime 0.8170719956979156
longitudinalPlan.solverExecutionTime 2.0179999992251396 longitudinalPlan.solverExecutionTime 0.5619999719783664
controlsd controlsd
Data sampled 78.909759 Data sampled 70.217763
Events updated 79.711884 Events updated 71.037178
sendcan published 80.721038 sendcan published 72.278775
controlsState published 81.081398 controlsState published 72.825226
Data sampled 88.663748 Data sampled 80.008354
Events updated 89.535403 Events updated 80.787666
sendcan published 90.587889 sendcan published 81.849682
controlsState published 91.019707 controlsState published 82.238323
Data sampled 98.667003 Data sampled 90.521123
Events updated 99.661261 Events updated 91.626003
sendcan published 100.776507 sendcan published 93.413218
controlsState published 101.198794 controlsState published 94.143989
Data sampled 108.967078 Data sampled 100.991497
Events updated 109.95842 Events updated 101.973774
sendcan published 111.263142 sendcan published 103.565575
controlsState published 111.678085 controlsState published 104.146088
Data sampled 118.574923 Data sampled 110.284387
Events updated 119.608555 Events updated 111.183541
sendcan published 120.73427 sendcan published 112.981692
controlsState published 121.111036 controlsState published 113.731994
Data sampled 128.596408
Events updated 129.382283
sendcan published 130.330083
controlsState published 130.676485
boardd boardd
sending sendcan to panda: 250027001751393037323631 90.7257 sending sendcan to panda: 250027001751393037323631 81.928119
sendcan sent to panda: 250027001751393037323631 91.078143 sendcan sent to panda: 250027001751393037323631 82.164834
sending sendcan to panda: 250027001751393037323631 100.941766 sending sendcan to panda: 250027001751393037323631 93.569986
sendcan sent to panda: 250027001751393037323631 101.306865 sendcan sent to panda: 250027001751393037323631 93.92795
sending sendcan to panda: 250027001751393037323631 111.411786 sending sendcan to panda: 250027001751393037323631 103.689167
sendcan sent to panda: 250027001751393037323631 111.754074 sendcan sent to panda: 250027001751393037323631 104.012235
sending sendcan to panda: 250027001751393037323631 120.875987 sending sendcan to panda: 250027001751393037323631 113.109555
sendcan sent to panda: 250027001751393037323631 121.188535 sendcan sent to panda: 250027001751393037323631 113.525487
sending sendcan to panda: 250027001751393037323631 130.454248 sending sendcan to panda: 250027001751393037323631 122.508434
sendcan sent to panda: 250027001751393037323631 130.757994 sendcan sent to panda: 250027001751393037323631 122.834314
sending sendcan to panda: 250027001751393037323631 140.353234
``` ```

16
tools/latencylogger/latency_logger.py
Unescape View File

@ -175,17 +175,18 @@ def print_timestamps(timestamps, durations, start_times, relative):
for event, time in durations[frame_id][service]: for event, time in durations[frame_id][service]:
print(" "+'%-53s%-53s' %(event, str(time*1000))) print(" "+'%-53s%-53s' %(event, str(time*1000)))
def graph_timestamps(timestamps, start_times, end_times, relative, title=""): def graph_timestamps(timestamps, start_times, end_times, relative, offset_services=False, title=""):
# mpld3 doesn't convert properly to D3 font sizes # mpld3 doesn't convert properly to D3 font sizes
plt.rcParams.update({'font.size': 18}) plt.rcParams.update({'font.size': 18})
t0 = find_t0(start_times) t0 = find_t0(start_times)
fig, ax = plt.subplots() fig, ax = plt.subplots()
ax.set_xlim(0, 150 if relative else 750) ax.set_xlim(0, 130 if relative else 750)
ax.set_ylim(0, 15) ax.set_ylim(0, 17)
ax.set_xlabel('Time (milliseconds)') ax.set_xlabel('Time (milliseconds)')
ax.set_ylabel('Frame ID')
colors = ['blue', 'green', 'red', 'yellow', 'purple'] colors = ['blue', 'green', 'red', 'yellow', 'purple']
offsets = [[0, -5*j] for j in range(len(SERVICES))] if offset_services else None
height = 0.3 if offset_services else 0.9
assert len(colors) == len(SERVICES), 'Each service needs a color' assert len(colors) == len(SERVICES), 'Each service needs a color'
points = {"x": [], "y": [], "labels": []} points = {"x": [], "y": [], "labels": []}
@ -202,16 +203,16 @@ def graph_timestamps(timestamps, start_times, end_times, relative, title=""):
points['x'].append((event[1]-t0)/1e6) points['x'].append((event[1]-t0)/1e6)
points['y'].append(i) points['y'].append(i)
points['labels'].append(event[0]) points['labels'].append(event[0])
ax.broken_barh(service_bars, (i-0.45, 0.9), facecolors=(colors), alpha=0.5) ax.broken_barh(service_bars, (i-height/2, height), facecolors=(colors), alpha=0.5, offsets=offsets)
scatter = ax.scatter(points['x'], points['y'], marker='d', edgecolor='black') scatter = ax.scatter(points['x'], points['y'], marker='d', edgecolor='black')
tooltip = mpld3.plugins.PointLabelTooltip(scatter, labels=points['labels']) tooltip = mpld3.plugins.PointLabelTooltip(scatter, labels=points['labels'])
mpld3.plugins.connect(fig, tooltip) mpld3.plugins.connect(fig, tooltip)
plt.title(title) plt.title(title)
# Set size relative window size is not trivial: https://github.com/mpld3/mpld3/issues/65
fig.set_size_inches(18, 9) fig.set_size_inches(18, 9)
plt.legend(handles=[mpatches.Patch(color=colors[i], label=SERVICES[i]) for i in range(len(SERVICES))]) plt.legend(handles=[mpatches.Patch(color=colors[i], label=SERVICES[i]) for i in range(len(SERVICES))])
return fig return fig
def get_timestamps(lr): def get_timestamps(lr):
@ -226,6 +227,7 @@ if __name__ == "__main__":
parser.add_argument("--relative", action="store_true", help="Make timestamps relative to the start of each frame") parser.add_argument("--relative", action="store_true", help="Make timestamps relative to the start of each frame")
parser.add_argument("--demo", action="store_true", help="Use the demo route instead of providing one") parser.add_argument("--demo", action="store_true", help="Use the demo route instead of providing one")
parser.add_argument("--plot", action="store_true", help="If a plot should be generated") parser.add_argument("--plot", action="store_true", help="If a plot should be generated")
parser.add_argument("--offset", action="store_true", help="Vertically offset service to better visualize overlap")
parser.add_argument("route_or_segment_name", nargs='?', help="The route to print") parser.add_argument("route_or_segment_name", nargs='?', help="The route to print")
if len(sys.argv) == 1: if len(sys.argv) == 1:
@ -239,4 +241,4 @@ if __name__ == "__main__":
data, _ = get_timestamps(lr) data, _ = get_timestamps(lr)
print_timestamps(data['timestamp'], data['duration'], data['start'], args.relative) print_timestamps(data['timestamp'], data['duration'], data['start'], args.relative)
if args.plot: if args.plot:
mpld3.show(graph_timestamps(data['timestamp'], data['start'], data['end'], args.relative, r)) mpld3.show(graph_timestamps(data['timestamp'], data['start'], data['end'], args.relative, offset_services=args.offset, title=r))

Write Preview
Loading…
Cancel
Save