Commit b3455555 authored by Jakob Bornecrantz's avatar Jakob Bornecrantz
Browse files

u/trace_marker: Use Percetto/Perfetto for tracing

parent 5c916fd7
......@@ -121,6 +121,7 @@ if(CMAKE_SYSTEM_NAME STREQUAL "Linux")
)
pkg_check_modules(SURVIVE IMPORTED_TARGET survive)
pkg_check_modules(PERCETTO percetto)
else()
find_package(OpenGL)
endif()
......@@ -193,7 +194,7 @@ cmake_dependent_option(XRT_HAVE_FFMPEG "Enable ffmpeg testing video driver" ON "
cmake_dependent_option(XRT_HAVE_SDL2 "Enable use of SDL2" ON "SDL2_FOUND AND XRT_HAVE_OPENGL" OFF)
cmake_dependent_option(XRT_HAVE_SYSTEM_CJSON "Enable cJSON from system, instead of bundled source" ON "CJSON_FOUND" OFF)
cmake_dependent_option(XRT_HAVE_GST "Enable gstreamer" ON "GST_FOUND" OFF)
cmake_dependent_option(XRT_HAVE_PERCETTO "Enable percetto support" ON "PERCETTO_FOUND" OFF)
cmake_dependent_option(XRT_BUILD_DRIVER_PSVR "Enable PSVR HMD driver" ON "HIDAPI_FOUND" OFF)
cmake_dependent_option(XRT_BUILD_DRIVER_RS "Enable RealSense device driver" ON "realsense2_FOUND" OFF)
......@@ -351,6 +352,7 @@ message(STATUS "# OPENCV: ${XRT_HAVE_OPENCV}")
message(STATUS "# LIBUVC: ${XRT_HAVE_LIBUVC}")
message(STATUS "# FFMPEG: ${XRT_HAVE_FFMPEG}")
message(STATUS "# SDL2: ${XRT_HAVE_SDL2}")
message(STATUS "# PERCETTO: ${XRT_HAVE_PERCETTO}")
message(STATUS "# SYSTEM_CJSON: ${XRT_HAVE_SYSTEM_CJSON}")
message(STATUS "#")
message(STATUS "# FEATURE_COMPOSITOR_MAIN: ${XRT_FEATURE_COMPOSITOR_MAIN}")
......
......@@ -19,6 +19,7 @@ getting started information and general documentation.
* @ref writing-driver (**not complete**)
* @ref ipc-design
* @ref frame-timing
* @ref tracing
## Source layout
......
# Tracing support {#tracing}
<!--
Copyright 2021, Collabora, Ltd. and the Monado contributors
SPDX-License-Identifier: BSL-1.0
-->
## Requirements
Monado uses the [Perfetto][]/[Percetto][] framework for tracining support, you
need to first build and install [Percetto][] in a place where CMake can find it.
Build [Perfetto][] (you will have gotten the source at least as part of build
[Percetto][]). It is a good idea to familiarise yourself with Perfetto before
proceeding. You then need to build Monado with CMake and give make sure
`XRT_FEATURE_TRACING` is enabled.
* Build and install [Percetto][].
* Build and get [Perfetto][] running.
* Build Monado with CMake and with `XRT_FEATURE_TRACING` being `ON`.
## Running
Save the following file to `data_events.cfg`, next to your perfetto folder.
Please refer to [Perfetto][] documentation about the format and options of this
config file, but the most important bits is the `tracker_event` section.
```c
flush_period_ms: 30000
incremental_state_config {
clear_period_ms: 500
}
buffers: {
size_kb: 63488
fill_policy: DISCARD
}
# This is the important bit, this enables all data events from Monado.
data_sources: {
config: {
name: "track_event"
target_buffer: 0
}
}
```
Then run the following commands before launching Monado.
```bash
# Start the daemon.
# Only needs to be run once and keeps running.
./perfetto/out/linux_clang_release/traced &
# Start the daemon ftrace probes daemon.
# Only needs to be run once and keeps running.
# Not needed with the above config.
./perfetto/out/linux_clang_release/traced_probes &
# When you want to run a capture do and then run Monado.
./perfetto/out/linux_clang_release/perfetto --txt -c data_events.cfg -o /tmp/trace.protobuf
```
[Perfetto]: https://perfetto.dev
[Percetto]: https://github.com/olvaffe/percetto
......@@ -230,6 +230,11 @@ if(XRT_HAVE_SYSTEM_CJSON)
else()
target_link_libraries(aux_util PUBLIC xrt-external-cjson)
endif()
# For u_trace_marker
if(XRT_HAVE_PERCETTO)
target_link_libraries(aux_util PRIVATE ${PERCETTO_LINK_LIBRARIES})
target_include_directories(aux_util PUBLIC ${PERCETTO_INCLUDE_DIRS})
endif()
if(XRT_HAVE_LIBBSD)
target_include_directories(aux_util SYSTEM PRIVATE ${LIBBSD_INCLUDE_DIRS})
target_link_libraries(aux_util PUBLIC ${LIBBSD_LIBRARIES})
......@@ -290,7 +295,7 @@ endif()
if(XRT_HAVE_VULKAN)
# Vulkan library.
add_library(aux_vk STATIC ${VK_SOURCE_FILES})
target_link_libraries(aux_vk PUBLIC aux_os)
target_link_libraries(aux_vk PUBLIC aux_os aux_util)
target_link_libraries(aux_vk PUBLIC Vulkan::Vulkan)
target_include_directories(aux_vk PUBLIC ${Vulkan_INCLUDE_DIR})
if(ANDROID)
......
......@@ -468,7 +468,117 @@ dt_info(struct u_frame_timing *uft,
f->present_margin_ns, //
present_margin_ms); //
COMP_TRACE_DATA(U_TRACE_DATA_TYPE_TIMING_FRAME, *f);
if (!U_TRACE_CATEGORY_IS_ENABLED(timing)) {
return;
}
#define TE_BEG(TRACK, TIME, NAME) U_TRACE_EVENT_BEGIN_ON_TRACK_DATA(timing, TRACK, TIME, NAME, PERCETTO_I(f->frame_id))
#define TE_END(TRACK, TIME) U_TRACE_EVENT_END_ON_TRACK(timing, TRACK, TIME)
/*
*
* CPU
*
*/
TE_BEG(rt_cpu, f->when_predict_ns, "sleep");
TE_END(rt_cpu, f->wake_up_time_ns);
uint64_t oversleep_start_ns = f->wake_up_time_ns + 1;
if (f->when_woke_ns > oversleep_start_ns) {
TE_BEG(rt_cpu, oversleep_start_ns, "oversleep");
TE_END(rt_cpu, f->when_woke_ns);
}
/*
*
* GPU
*
*/
uint64_t gpu_end_ns = f->actual_present_time_ns - f->present_margin_ns;
if (gpu_end_ns > f->when_submitted_ns) {
TE_BEG(rt_gpu, f->when_submitted_ns, "gpu");
TE_END(rt_gpu, gpu_end_ns);
} else {
TE_BEG(rt_gpu, gpu_end_ns, "gpu-time-travel");
TE_END(rt_gpu, f->when_submitted_ns);
}
/*
*
* Margin
*
*/
if (gpu_end_ns < f->desired_present_time_ns) {
TE_BEG(rt_margin, gpu_end_ns, "margin");
TE_END(rt_margin, f->desired_present_time_ns);
}
/*
*
* ERROR
*
*/
if (!is_within_half_ms(f->actual_present_time_ns, f->desired_present_time_ns)) {
if (f->actual_present_time_ns > f->desired_present_time_ns) {
TE_BEG(rt_error, f->desired_present_time_ns, "slippage");
TE_END(rt_error, f->actual_present_time_ns);
} else {
TE_BEG(rt_error, f->actual_present_time_ns, "run-ahead");
TE_END(rt_error, f->desired_present_time_ns);
}
}
/*
*
* Info
*
*/
if (f->when_infoed_ns >= f->actual_present_time_ns) {
TE_BEG(rt_info, f->actual_present_time_ns, "info");
TE_END(rt_info, f->when_infoed_ns);
} else {
TE_BEG(rt_info, f->when_infoed_ns, "info_before");
TE_END(rt_info, f->actual_present_time_ns);
}
/*
*
* Present
*
*/
if (f->actual_present_time_ns != f->earliest_present_time_ns) {
U_TRACE_INSTANT_ON_TRACK(timing, rt_present, f->earliest_present_time_ns, "earliest");
}
if (!is_within_half_ms(f->desired_present_time_ns, f->earliest_present_time_ns)) {
U_TRACE_INSTANT_ON_TRACK(timing, rt_present, f->desired_present_time_ns, "predicted");
}
U_TRACE_INSTANT_ON_TRACK(timing, rt_present, f->actual_present_time_ns, "vsync");
/*
*
* Compositor time
*
*/
TE_BEG(rt_allotted, f->wake_up_time_ns, "allotted");
TE_END(rt_allotted, f->wake_up_time_ns + f->current_app_time_ns);
#undef TE_BEG
#undef TE_END
}
static void
......@@ -510,152 +620,3 @@ u_ft_display_timing_create(uint64_t estimated_frame_period_ns, struct u_frame_ti
return XRT_SUCCESS;
}
/*
*
* Tracing functions.
*
*/
#define PID_NR 42
#define TID_NORMAL 43
#define TID_GPU 44
#define TID_INFO 45
#define TID_FRAME 46
#define TID_ERROR 47
#define TID_APP 48
XRT_MAYBE_UNUSED static void
trace_event(FILE *file, const char *name, uint64_t when_ns)
{
if (file == NULL) {
return;
}
// clang-format off
fprintf(file,
",\n"
"\t\t{\n"
"\t\t\t\"ph\": \"i\",\n"
"\t\t\t\"name\": \"%s\",\n"
"\t\t\t\"ts\": %" PRIu64 ".%03" PRIu64 ",\n"
"\t\t\t\"pid\": %u,\n"
"\t\t\t\"tid\": %u,\n"
"\t\t\t\"s\": \"g\",\n"
"\t\t\t\"args\": {}\n"
"\t\t}",
name, when_ns / 1000, when_ns % 1000, PID_NR, TID_NORMAL);
// clang-format off
}
static void
trace_event_id(FILE *file, const char *name, int64_t frame_id, uint64_t when_ns)
{
if (file == NULL) {
return;
}
// clang-format off
fprintf(file,
",\n"
"\t\t{\n"
"\t\t\t\"ph\": \"i\",\n"
"\t\t\t\"name\": \"%s\",\n"
"\t\t\t\"ts\": %" PRIu64 ".%03" PRIu64 ",\n"
"\t\t\t\"pid\": %u,\n"
"\t\t\t\"tid\": %u,\n"
"\t\t\t\"s\": \"g\",\n"
"\t\t\t\"args\": {"
"\t\t\t\t\"id\": %" PRIi64 "\n"
"\t\t\t}\n"
"\t\t}",
name, when_ns / 1000, when_ns % 1000, PID_NR, TID_NORMAL, frame_id);
// clang-format off
}
static void
trace_begin_id(FILE *file, uint32_t tid, const char *name, int64_t frame_id, const char *cat, uint64_t when_ns)
{
if (file == NULL) {
return;
}
char temp[256];
snprintf(temp, sizeof(temp), "%s %" PRIi64, name, frame_id);
u_trace_maker_write_json_begin(file, PID_NR, tid, temp, cat, when_ns);
}
static void
trace_end(FILE *file, uint32_t tid, uint64_t when_ns)
{
u_trace_maker_write_json_end(file, PID_NR, tid, when_ns);
}
static void
trace_frame(FILE *file, struct frame *f)
{
trace_begin_id(file, TID_NORMAL, "sleep", f->frame_id, "sleep", f->when_predict_ns);
trace_end(file, TID_NORMAL, f->wake_up_time_ns);
if (f->when_woke_ns > f->wake_up_time_ns) {
trace_begin_id(file, TID_NORMAL, "oversleep", f->frame_id, "sleep", f->wake_up_time_ns);
trace_end(file, TID_NORMAL, f->when_woke_ns);
}
if (!is_within_half_ms(f->actual_present_time_ns, f->desired_present_time_ns)) {
if (f->actual_present_time_ns > f->desired_present_time_ns) {
trace_begin_id(file, TID_ERROR, "slippage", f->frame_id, "slippage",
f->desired_present_time_ns);
trace_end(file, TID_ERROR, f->actual_present_time_ns);
} else {
trace_begin_id(file, TID_ERROR, "run-ahead", f->frame_id, "run-ahead",
f->actual_present_time_ns);
trace_end(file, TID_ERROR, f->desired_present_time_ns);
}
}
uint64_t gpu_end_ns = f->actual_present_time_ns - f->present_margin_ns;
if (gpu_end_ns > f->when_submitted_ns) {
trace_begin_id(file, TID_GPU, "gpu", f->frame_id, "gpu", f->when_submitted_ns);
trace_end(file, TID_GPU, gpu_end_ns);
} else {
trace_begin_id(file, TID_GPU, "gpu-time-travel", f->frame_id, "gpu-time-travel", gpu_end_ns);
trace_end(file, TID_GPU, f->when_submitted_ns);
}
if (f->when_infoed_ns >= f->actual_present_time_ns) {
trace_begin_id(file, TID_INFO, "info", f->frame_id, "info", f->actual_present_time_ns);
trace_end(file, TID_INFO, f->when_infoed_ns);
} else {
trace_begin_id(file, TID_INFO, "info before", f->frame_id, "info", f->when_infoed_ns);
trace_end(file, TID_INFO, f->actual_present_time_ns);
}
trace_event_id(file, "vsync", f->frame_id, f->earliest_present_time_ns);
if (f->actual_present_time_ns != f->earliest_present_time_ns) {
trace_event_id(file, "flip", f->frame_id, f->actual_present_time_ns);
}
trace_begin_id(file, TID_APP, "app", f->frame_id, "app", f->wake_up_time_ns);
trace_end(file, TID_APP, f->wake_up_time_ns + f->current_app_time_ns);
}
void
u_ft_write_json(FILE *file, void *data)
{
trace_frame(file, (struct frame *)data);
}
void
u_ft_write_json_metadata(FILE *file)
{
u_trace_maker_write_json_metadata(file, PID_NR, TID_NORMAL, "1 RendererThread");
u_trace_maker_write_json_metadata(file, PID_NR, TID_GPU, "2 GPU");
u_trace_maker_write_json_metadata(file, PID_NR, TID_INFO, "3 Info");
u_trace_maker_write_json_metadata(file, PID_NR, TID_FRAME, "4 FrameTiming");
u_trace_maker_write_json_metadata(file, PID_NR, TID_ERROR, "5 Slips");
u_trace_maker_write_json_metadata(file, PID_NR, TID_APP, "6 App time");
fflush(file);
}
......@@ -350,7 +350,23 @@ rt_mark_delivered(struct u_render_timing *urt, int64_t frame_id)
do_iir_filter(&rt->app.draw_time_ns, IIR_ALPHA_LT, IIR_ALPHA_GT, diff_draw_ns);
// Trace the data.
COMP_TRACE_DATA(U_TRACE_DATA_TYPE_TIMING_RENDER, *f);
#define TE_BEG(TRACK, TIME, NAME) U_TRACE_EVENT_BEGIN_ON_TRACK_DATA(timing, TRACK, TIME, NAME, PERCETTO_I(f->frame_id))
#define TE_END(TRACK, TIME) U_TRACE_EVENT_END_ON_TRACK(timing, TRACK, TIME)
if (U_TRACE_CATEGORY_IS_ENABLED(timing)) {
TE_BEG(ft_cpu, f->when.predicted_ns, "sleep");
TE_END(ft_cpu, f->when.wait_woke_ns);
uint64_t cpu_start_ns = f->when.wait_woke_ns + 1;
TE_BEG(ft_cpu, cpu_start_ns, "cpu");
TE_END(ft_cpu, f->when.begin_ns);
TE_BEG(ft_draw, f->when.begin_ns, "draw");
TE_END(ft_draw, f->when.delivered_ns);
}
#undef TE_BEG
#undef TE_END
// Reset the frame.
f->state = U_RT_READY;
......@@ -406,55 +422,3 @@ u_rt_create(struct u_render_timing **out_urt)
return XRT_SUCCESS;
}
/*
*
* Tracing data.
*
*/
#define PID_NR 43
#define TID_ESTIMATED_CPU 20
#define TID_ESTIMATED_DRAW 21
#define TID_ACTUAL_CPU 22
#define TID_ACTUAL_DRAW 23
static void
trace_begin_id(FILE *file, uint32_t tid, const char *name, int64_t frame_id, const char *cat, uint64_t when_ns)
{
char temp[256];
snprintf(temp, sizeof(temp), "%s %" PRIi64, name, frame_id);
u_trace_maker_write_json_begin(file, PID_NR, tid, temp, cat, when_ns);
}
static void
trace_end(FILE *file, uint32_t tid, uint64_t when_ns)
{
u_trace_maker_write_json_end(file, PID_NR, tid, when_ns);
}
void
u_rt_write_json_metadata(FILE *file)
{
u_trace_maker_write_json_metadata(file, PID_NR, TID_ESTIMATED_CPU, "1 CPU estimated");
u_trace_maker_write_json_metadata(file, PID_NR, TID_ESTIMATED_DRAW, "2 Draw estimated");
u_trace_maker_write_json_metadata(file, PID_NR, TID_ACTUAL_CPU, "1 CPU actual");
u_trace_maker_write_json_metadata(file, PID_NR, TID_ACTUAL_DRAW, "2 Draw actual");
}
void
u_rt_write_json(FILE *file, void *data)
{
struct u_rt_frame *f = (struct u_rt_frame *)data;
trace_begin_id(file, TID_ACTUAL_CPU, "sleep", f->frame_id, "sleep", f->when.predicted_ns);
trace_end(file, TID_ACTUAL_CPU, f->when.wait_woke_ns);
trace_begin_id(file, TID_ACTUAL_CPU, "cpu", f->frame_id, "cpu", f->when.wait_woke_ns);
trace_end(file, TID_ACTUAL_CPU, f->when.begin_ns);
trace_begin_id(file, TID_ACTUAL_DRAW, "draw", f->frame_id, "draw", f->when.begin_ns);
trace_end(file, TID_ACTUAL_DRAW, f->when.delivered_ns);
}
......@@ -2,183 +2,87 @@
// SPDX-License-Identifier: BSL-1.0
/*!
* @file
* @brief Trace marking debugging code.
* @brief Tracing support code, see @ref tracing.
* @author Jakob Bornecrantz <jakob@collabora.com>
* @ingroup aux_util
*/
// This needs to be first.
#define _GNU_SOURCE
#include "xrt/xrt_compiler.h"
#include "xrt/xrt_config_os.h"
#include "u_trace_marker.h"
#ifdef XRT_OS_LINUX
#include <inttypes.h>
#include <unistd.h>
#include <sys/types.h>
#include <stdio.h>
#include <fcntl.h>
#include <stdarg.h>
#include <pthread.h>
#include <sys/stat.h>
#include "xrt/xrt_config_have.h"
#define TRACE_MARKER_FILENAME "/sys/kernel/tracing/trace_marker"
#include "os/os_time.h"
int u_trace_xrt_fd = -1;
int u_trace_ipc_fd = -1;
int u_trace_oxr_fd = -1;
int u_trace_comp_fd = -1;
#include "util/u_trace_marker.h"
void
u_tracer_maker_init(void)
{
int fd = open(TRACE_MARKER_FILENAME, O_WRONLY);
#ifdef XRT_FEATURE_TRACING
u_trace_oxr_fd = fd;
u_trace_ipc_fd = fd;
u_trace_xrt_fd = fd;
u_trace_comp_fd = fd;
}
#include <inttypes.h>
void
u_trace_enter(int fd, const char *func)
{
if (fd < 0) {
return;
}
PERCETTO_CATEGORY_DEFINE(U_TRACE_CATEGORIES)
char tmp[512];
ssize_t len = snprintf(tmp, sizeof(tmp), "B %u %s", getpid(), func);
if (len > 0) {
len = write(fd, tmp, len);
}
}
PERCETTO_TRACK_DEFINE(rt_cpu, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_allotted, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_gpu, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_margin, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_error, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_info, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_present, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(ft_cpu, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(ft_draw, PERCETTO_TRACK_EVENTS);
void
u_trace_leave(int fd, const char *func)
u_tracer_maker_init(enum u_trace_which which)
{
if (fd < 0) {
int ret = PERCETTO_INIT(PERCETTO_CLOCK_MONOTONIC);
if (ret != 0) {
return;
}
char tmp[512];
ssize_t len = snprintf(tmp, sizeof(tmp), "E %u %s", getpid(), func);
if (len > 0) {
len = write(fd, tmp, len);
I_PERCETTO_TRACK_PTR(rt_cpu)->name = "RT 1 Sleep";
I_PERCETTO_TRACK_PTR(rt_allotted)->name = "RT 2 Allotted time";
I_PERCETTO_TRACK_PTR(rt_gpu)->name = "RT 3 GPU";
I_PERCETTO_TRACK_PTR(rt_margin)->name = "RT 4 Margin";
I_PERCETTO_TRACK_PTR(rt_error)->name = "RT 5 Error";
I_PERCETTO_TRACK_PTR(rt_info)->name = "RT 6 Info";
I_PERCETTO_TRACK_PTR(rt_present)->name = "RT 7 Present";
I_PERCETTO_TRACK_PTR(ft_cpu)->name = "FT 1 App";
I_PERCETTO_TRACK_PTR(ft_draw)->name = "FT 2 Draw";
if (which == U_TRACE_WHICH_SERVICE) {
PERCETTO_REGISTER_TRACK(rt_cpu);
PERCETTO_REGISTER_TRACK(rt_allotted);
PERCETTO_REGISTER_TRACK(rt_gpu);
PERCETTO_REGISTER_TRACK(rt_margin);
PERCETTO_REGISTER_TRACK(rt_error);
PERCETTO_REGISTER_TRACK(rt_info);
PERCETTO_REGISTER_TRACK(rt_present);
PERCETTO_REGISTER_TRACK(ft_cpu);
PERCETTO_REGISTER_TRACK(ft_draw);
}
}
void
u_trace_data(int fd, enum u_trace_data_type type, void *data, size_t size)
{
char tmp[1024 * 8];
ssize_t len = snprintf(tmp, sizeof(tmp), "r %u %u %u ", getpid(), type, (uint32_t)size);
if (len <= 0) {
return;
}
/*
*
* Hack to get consistent names.
* https://github.com/olvaffe/percetto/issues/15
*
*/