Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Disambiguate frame id in latencylogger #24164

Merged
merged 9 commits into from
Apr 19, 2022
Merged

Disambiguate frame id in latencylogger #24164

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
b368772
add tools to disambiguate frame id
lukaspetersson Apr 7, 2022
88b9c2b
Update selfdrive/camerad/cameras/camera_qcom2.cc
lukaspetersson Apr 8, 2022
e3755f9
merge + clean LOGTF
lukaspetersson Apr 14, 2022
c680d79
Merge remote-tracking branch 'refs/remotes/origin/latencylogger_disam…
lukaspetersson Apr 14, 2022
060245c
bug fix
Apr 14, 2022
5ae4423
remove duplicate code
lukaspetersson Apr 15, 2022
76d0fec
merge
lukaspetersson Apr 15, 2022
6bc2690
PR comments
lukaspetersson Apr 19, 2022
0d5a38a
bug fix
lukaspetersson Apr 19, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions selfdrive/camerad/cameras/camera_qcom2.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1084,10 +1084,10 @@ void process_road_camera(MultiCameraState *s, CameraState *c, int cnt) {
if ((c == &s->road_cam && env_send_road) || (c == &s->wide_road_cam && env_send_wide_road)) {
framed.setImage(get_frame_image(b));
}
LOGT("%s: Image set", c == &s->road_cam ? "RoadCamera" : "WideRoadCamera");
LOGTF(c->buf.cur_frame_data.frame_id, "%s: Image set", c == &s->road_cam ? "RoadCamera" : "WideRoadCamera");
if (c == &s->road_cam) {
framed.setTransform(b->yuv_transform.v);
LOGT("%s: Transformed", c == &s->road_cam ? "RoadCamera" : "WideRoadCamera");
LOGTF(c->buf.cur_frame_data.frame_id, "%s: Transformed", c == &s->road_cam ? "RoadCamera" : "WideRoadCamera");
lukaspetersson marked this conversation as resolved.
Show resolved Hide resolved
}
s->pm->send(c == &s->road_cam ? "roadCameraState" : "wideRoadCameraState", msg);

Expand Down
58 changes: 39 additions & 19 deletions selfdrive/common/swaglog.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -72,14 +72,9 @@ static void log(int levelnum, const char* filename, int lineno, const char* func
char levelnum_c = levelnum;
zmq_send(s.sock, (levelnum_c + log_s).c_str(), log_s.length() + 1, ZMQ_NOBLOCK);
}
static void cloudlog_common(int levelnum, bool is_timestamp, const char* filename, int lineno, const char* func,
const char* fmt, va_list args) {
char* msg_buf = nullptr;
int ret = vasprintf(&msg_buf, fmt, args);
if (ret <= 0 || !msg_buf) return;

static void cloudlog_common(int levelnum, const char* filename, int lineno, const char* func,
char* msg_buf, json11::Json::object msg_j={}) {
std::lock_guard lk(s.lock);

if (!s.initialized) s.initialize();

json11::Json::object log_j = json11::Json::object {
Expand All @@ -90,17 +85,10 @@ static void cloudlog_common(int levelnum, bool is_timestamp, const char* filenam
{"funcname", func},
{"created", seconds_since_epoch()}
};

if (is_timestamp) {
json11::Json::object tspt_j = json11::Json::object {
{"timestamp", json11::Json::object{
{"event", msg_buf},
{"time", std::to_string(nanos_since_boot())}}
}
};
log_j["msg"] = tspt_j;
} else {
if (msg_j.empty()) {
log_j["msg"] = msg_buf;
} else {
log_j["msg"] = msg_j;
}

std::string log_s = ((json11::Json)log_j).dump();
Expand All @@ -112,15 +100,47 @@ void cloudlog_e(int levelnum, const char* filename, int lineno, const char* func
const char* fmt, ...){
va_list args;
va_start(args, fmt);
cloudlog_common(levelnum, false, filename, lineno, func, fmt, args);
char* msg_buf = nullptr;
int ret = vasprintf(&msg_buf, fmt, args);
va_end(args);
if (ret <= 0 || !msg_buf) return;
cloudlog_common(levelnum, filename, lineno, func, msg_buf);
}

void cloudlog_t(int levelnum, const char* filename, int lineno, const char* func,
const char* fmt, ...){
if (!LOG_TIMESTAMPS) return;
va_list args;
va_start(args, fmt);
cloudlog_common(levelnum, true, filename, lineno, func, fmt, args);
char* msg_buf = nullptr;
int ret = vasprintf(&msg_buf, fmt, args);
va_end(args);
if (ret <= 0 || !msg_buf) return;
json11::Json::object tspt_j = json11::Json::object{
{"timestamp", json11::Json::object{
{"event", msg_buf},
{"time", std::to_string(nanos_since_boot())}}
}
};
cloudlog_common(levelnum, filename, lineno, func, msg_buf, tspt_j);
}

void cloudlog_t_f(int levelnum, int frame_id, const char* filename, int lineno, const char* func,
const char* fmt, ...){
if (!LOG_TIMESTAMPS) return;
va_list args;
va_start(args, fmt);
char* msg_buf = nullptr;
int ret = vasprintf(&msg_buf, fmt, args);
va_end(args);
if (ret <= 0 || !msg_buf) return;
json11::Json::object tspt_j = json11::Json::object{
{"timestamp", json11::Json::object{
{"event", msg_buf},
{"frame_id", frame_id},
{"time", std::to_string(nanos_since_boot())}}
}
};
cloudlog_common(levelnum, filename, lineno, func, msg_buf, tspt_j);
}

10 changes: 9 additions & 1 deletion selfdrive/common/swaglog.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,9 @@ void cloudlog_e(int levelnum, const char* filename, int lineno, const char* func
void cloudlog_t(int levelnum, const char* filename, int lineno, const char* func,
const char* fmt, ...) /*__attribute__ ((format (printf, 6, 7)))*/;

void cloudlog_t_f(int levelnum, int frame_id, const char* filename, int lineno, const char* func,
const char* fmt, ...) /*__attribute__ ((format (printf, 6, 7)))*/;

#define cloudlog(lvl, fmt, ...) cloudlog_e(lvl, __FILE__, __LINE__, \
__func__, \
fmt, ## __VA_ARGS__);
Expand All @@ -23,6 +26,10 @@ void cloudlog_t(int levelnum, const char* filename, int lineno, const char* func
__func__, \
fmt, ## __VA_ARGS__);

#define cloudlog_t_f_m(lvl, frame_id, fmt, ...) cloudlog_t_f(lvl, frame_id, __FILE__, __LINE__, \
__func__, \
fmt, ## __VA_ARGS__);

#define cloudlog_rl(burst, millis, lvl, fmt, ...) \
{ \
static uint64_t __begin = 0; \
Expand Down Expand Up @@ -52,7 +59,8 @@ void cloudlog_t(int levelnum, const char* filename, int lineno, const char* func
} \
}

#define LOGT(fmt, ...) cloudlog_t_m(CLOUDLOG_DEBUG, fmt,## __VA_ARGS__)
#define LOGT(fmt, ...) cloudlog_t_m(CLOUDLOG_DEBUG, fmt, ## __VA_ARGS__)
#define LOGTF(frame_id, fmt, ...) cloudlog_t_f_m(CLOUDLOG_DEBUG, frame_id, fmt, ## __VA_ARGS__)
#define LOGD(fmt, ...) cloudlog(CLOUDLOG_DEBUG, fmt, ## __VA_ARGS__)
#define LOG(fmt, ...) cloudlog(CLOUDLOG_INFO, fmt, ## __VA_ARGS__)
#define LOGW(fmt, ...) cloudlog(CLOUDLOG_WARNING, fmt, ## __VA_ARGS__)
Expand Down
103 changes: 55 additions & 48 deletions tools/latencylogger/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ optional arguments:
--demo Use the demo route instead of providing one (default: False)
--plot If a plot should be generated (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 `LOGTF(frameId ,"msg")`.

## Examples
Plotting with relative starts each process at time=0 and gives a nice overview.
Expand All @@ -30,58 +31,64 @@ Plotting without relative provides info about the frames relative time.

Printed timestamps of a frame with internal durations.
```
Frame ID: 303
Frame ID: 371
camerad
roadCameraState start of frame 0.0
wideRoadCameraState start of frame 0.091926
RoadCamera: Image set 1.691696
RoadCamera: Transformed 1.812841
roadCameraState published 51.775466
wideRoadCameraState published 54.935164
roadCameraState.processingTime 1.6455530421808362
wideRoadCameraState.processingTime 4.790564067661762
wideRoadCameraState start of frame 0.0
roadCameraState start of frame 0.072395
wideRoadCameraState published 47.804745
WideRoadCamera: Image set 47.839849
roadCameraState published 48.319166
RoadCamera: Image set 48.354478
RoadCamera: Transformed 48.430258
wideRoadCameraState.processingTime 16.733376309275627
roadCameraState.processingTime 16.218071803450584
modeld
Image added 56.628788
Extra image added 57.459923
Execution finished 75.091306
modelV2 published 75.24797
modelV2.modelExecutionTime 20.00947669148445
Image added 51.346522
Extra image added 53.179467
Execution finished 71.584437
modelV2 published 71.76881
modelV2.modelExecutionTime 22.54236489534378
modelV2.gpuExecutionTime 0.0
plannerd
lateralPlan published 80.426861
longitudinalPlan published 85.722781
lateralPlan.solverExecutionTime 1.0600379901006818
longitudinalPlan.solverExecutionTime 1.3830000534653664
lateralPlan published 77.381862
longitudinalPlan published 84.207972
lateralPlan.solverExecutionTime 1.3547739945352077
longitudinalPlan.solverExecutionTime 2.0179999992251396
controlsd
Data sampled 89.436221
Events updated 90.356522
sendcan published 91.396092
controlsState published 91.77843
Data sampled 99.885876
Events updated 100.696855
sendcan published 101.600489
controlsState published 101.941839
Data sampled 110.087669
Events updated 111.025365
sendcan published 112.305921
controlsState published 112.70451
Data sampled 119.692803
Events updated 120.56774
sendcan published 121.735016
controlsState published 122.142823
Data sampled 129.264761
Events updated 130.024282
sendcan published 130.950364
controlsState published 131.281558
Data sampled 78.909759
Events updated 79.711884
sendcan published 80.721038
controlsState published 81.081398
Data sampled 88.663748
Events updated 89.535403
sendcan published 90.587889
controlsState published 91.019707
Data sampled 98.667003
Events updated 99.661261
sendcan published 100.776507
controlsState published 101.198794
Data sampled 108.967078
Events updated 109.95842
sendcan published 111.263142
controlsState published 111.678085
Data sampled 118.574923
Events updated 119.608555
sendcan published 120.73427
controlsState published 121.111036
Data sampled 128.596408
Events updated 129.382283
sendcan published 130.330083
controlsState published 130.676485
boardd
sending sendcan to panda: 250027001751393037323631 101.705487
sendcan sent to panda: 250027001751393037323631 102.042462
sending sendcan to panda: 250027001751393037323631 112.416961
sendcan sent to panda: 250027001751393037323631 112.792269
sending sendcan to panda: 250027001751393037323631 121.850952
sendcan sent to panda: 250027001751393037323631 122.231103
sending sendcan to panda: 250027001751393037323631 131.045206
sendcan sent to panda: 250027001751393037323631 131.351296
sending sendcan to panda: 250027001751393037323631 141.340592
sendcan sent to panda: 250027001751393037323631 141.700744
sending sendcan to panda: 250027001751393037323631 90.7257
sendcan sent to panda: 250027001751393037323631 91.078143
sending sendcan to panda: 250027001751393037323631 100.941766
sendcan sent to panda: 250027001751393037323631 101.306865
sending sendcan to panda: 250027001751393037323631 111.411786
sendcan sent to panda: 250027001751393037323631 111.754074
sending sendcan to panda: 250027001751393037323631 120.875987
sendcan sent to panda: 250027001751393037323631 121.188535
sending sendcan to panda: 250027001751393037323631 130.454248
sendcan sent to panda: 250027001751393037323631 130.757994
sending sendcan to panda: 250027001751393037323631 140.353234
```
26 changes: 18 additions & 8 deletions tools/latencylogger/latency_logger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -96,8 +96,7 @@ def find_frame_id(time, service, timestamps):
for frame_id in reversed(timestamps):
start, end = get_interval(frame_id, service, timestamps)
if start <= time <= end:
return frame_id
return -1
yield frame_id

## ASSUMES THAT AT LEAST ONE CLOUDLOG IS MADE IN CONTROLSD
def insert_cloudlogs(lr, timestamps):
Expand All @@ -115,13 +114,24 @@ def insert_cloudlogs(lr, timestamps):
# Filter out controlsd messages which arrive before the camera loop
continue

frame_id = latest_controls_frameid if service == "boardd" else find_frame_id(time, service, timestamps)
if frame_id > -1:
timestamps[frame_id][service].append((event, time))
if service == 'controlsd':
latest_controls_frameid = frame_id
if "frame_id" in jmsg['msg']['timestamp']:
timestamps[jmsg['msg']['timestamp']['frame_id']][service].append((event, time))
continue

if service == "boardd":
timestamps[latest_controls_frameid][service].append((event, time))
else:
failed_inserts += 1
frame_id_gen = find_frame_id(time, service, timestamps)
frame_id = next(frame_id_gen, False)
if frame_id:
if service == 'controlsd':
latest_controls_frameid = frame_id
if next(frame_id_gen, False):
event += " (warning: ambiguity)"
timestamps[frame_id][service].append((event, time))
else:
failed_inserts += 1
assert latest_controls_frameid > 0, "No timestamp in controlsd"
assert failed_inserts < len(timestamps), "Too many failed cloudlog inserts"

def print_timestamps(timestamps, durations ,relative):
Expand Down