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

Time profile of sdk #642

Draft
wants to merge 4 commits into
base: main
Choose a base branch
from
Draft

Time profile of sdk #642

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
e3c8f58
cmake: Add option to enable/disable time profiling
dNechita Apr 11, 2024
c1a5711
sdk: Time profile the requestFrame() from class CameraItof
dNechita Apr 11, 2024
32ff2c5
sdk: Time profile processBuffer from class BufferProcessor
dNechita Apr 11, 2024
97d8530
sdk: Time profile waiting for v4l2 buffer within processBuffer()
dNechita Apr 17, 2024
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
9 changes: 9 additions & 0 deletions CMakeLists.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,9 @@ option(NVIDIA "Set to ON when building on NVIDIA" OFF)
option(WITH_PROTOBUF_DEPENDENCY "Build with PROTOBUF dependency?" ON)
option(USE_DEPTH_COMPUTE_OPENSOURCE "Use an open source implementation?" OFF)

##################### Development/Testing Options #############################
option(TIME_PROFILING "Set to ON for displaying time execution for various core features" OFF)

################################## Git ########################################
include(FindGit OPTIONAL)
if (GIT_FOUND)
Expand Down Expand Up @@ -96,6 +99,12 @@ if (WITH_NETWORK)
add_definitions(-DHAS_NETWORK)
endif()

if (TIME_PROFILING)
add_definitions(-DTIME_PROFILING)
else()
remove_definitions(-DTIME_PROFILING)
endif()

set(RESOURCES_DIR "${CMAKE_BINARY_DIR}/resources")
make_directory(${RESOURCES_DIR})

Expand Down
61 changes: 59 additions & 2 deletions sdk/src/cameras/itof-camera/camera_itof.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -710,6 +710,12 @@ aditof::Status setAttributesByMode(aditof::Frame &frame,
}

aditof::Status CameraItof::requestFrame(aditof::Frame *frame) {
#ifdef TIME_PROFILING
using namespace std::chrono;

steady_clock::time_point rf_t0 = steady_clock::now();
#endif

using namespace aditof;
Status status = Status::OK;
ModeInfo::modeInfo aModeInfo;
Expand Down Expand Up @@ -748,25 +754,35 @@ aditof::Status CameraItof::requestFrame(aditof::Frame *frame) {
LOG(WARNING) << "getframe failed to allocated valid frame";
return status;
}

#ifdef TIME_PROFILING
steady_clock::time_point sgf_t0 = steady_clock::now();
#endif
status = m_depthSensor->getFrame(frameDataLocation);
#ifdef TIME_PROFILING
steady_clock::time_point sgf_t1 = steady_clock::now();
#endif
if (status != Status::OK) {
LOG(WARNING) << "Failed to get frame from device";
return status;
}

#ifdef TIME_PROFILING
steady_clock::time_point cxyz_t0 = steady_clock::now();
#endif
// The incoming sensor frames are already processed. Need to just create XYZ data
if (m_xyzEnabled) {
uint16_t *depthFrame;
uint16_t *xyzFrame;

frame->getData("depth", &depthFrame);
frame->getData("xyz", &xyzFrame);

Algorithms::ComputeXYZ((const uint16_t *)depthFrame, &m_xyzTable,
(int16_t *)xyzFrame, m_details.frameType.height,
m_details.frameType.width);
}
#ifdef TIME_PROFILING
steady_clock::time_point cxyz_t1 = steady_clock::now();
#endif

Metadata metadata;
status = frame->getMetadataStruct(metadata);
Expand Down Expand Up @@ -807,6 +823,47 @@ aditof::Status CameraItof::requestFrame(aditof::Frame *frame) {
memcpy(reinterpret_cast<uint8_t *>(metadataLocation),
reinterpret_cast<uint8_t *>(&metadata), sizeof(metadata));

#ifdef TIME_PROFILING
steady_clock::time_point rf_t1 = steady_clock::now();
#endif

#ifdef TIME_PROFILING
// Measure execution times, display statistics
auto request_frame_elapsed_time =
std::chrono::duration_cast<std::chrono::microseconds>(rf_t1 - rf_t0);
auto compute_xyz_elapsed_time =
std::chrono::duration_cast<std::chrono::microseconds>(cxyz_t1 -
cxyz_t0);
auto sensor_get_frame_elapsed_time =
std::chrono::duration_cast<std::chrono::microseconds>(sgf_t1 - sgf_t0);

auto total_profiled_time =
compute_xyz_elapsed_time + sensor_get_frame_elapsed_time;

std::cout << "CameraItof::requestFrame() took: "
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do you use std cout and not LOG(INFO) from glog?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The main reason was to easily align the lines being printed. For example:

CameraItof::requestFrame() took: 80011us
|--> DepthSensorInterface::getFrame() took: 49724us(62.1465%)
|--> Algorithms::computeXYZ() took: 29566us(36.9524%)
Total profiled time: 79290us(99.0989%)

Another reason is that this way it's easier/clearer to separate the application usual logging from the printing of the time profiling. When one activates time profiling the most important thing to spot are the time measurements.
Also GLOG prints this header at the beginning of each line which is much noise in this situation.

<< request_frame_elapsed_time.count() << "us" << std::endl;
std::cout << "|--> DepthSensorInterface::getFrame() took: "
<< sensor_get_frame_elapsed_time.count() << "us"
<< "("
<< ((double)sensor_get_frame_elapsed_time.count() /
request_frame_elapsed_time.count()) *
100.0
<< "%)" << std::endl;
std::cout << "|--> Algorithms::computeXYZ() took: "
<< compute_xyz_elapsed_time.count() << "us"
<< "("
<< ((double)compute_xyz_elapsed_time.count() /
request_frame_elapsed_time.count()) *
100.0
<< "%)" << std::endl;
std::cout << "Total profiled time: " << total_profiled_time.count() << "us"
<< "("
<< ((double)total_profiled_time.count() /
request_frame_elapsed_time.count()) *
100.0
<< "%)" << std::endl;
#endif

return Status::OK;
}

Expand Down
81 changes: 80 additions & 1 deletion sdk/src/connections/target/buffer_processor.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,10 @@

#include "buffer_processor.h"

#ifdef TIME_PROFILING
#include <chrono>
#endif

#define CLEAR(x) memset(&(x), 0, sizeof(x))

static int xioctl(int fh, unsigned int request, void *arg) {
Expand Down Expand Up @@ -208,6 +212,12 @@ aditof::Status BufferProcessor::setProcessorProperties(
}

aditof::Status BufferProcessor::processBuffer(uint16_t *buffer = nullptr) {
#ifdef TIME_PROFILING
using namespace std::chrono;

steady_clock::time_point pb_t0 = steady_clock::now();
#endif

using namespace aditof;
struct v4l2_buffer buf[4];
struct VideoDev *dev;
Expand All @@ -216,8 +226,13 @@ aditof::Status BufferProcessor::processBuffer(uint16_t *buffer = nullptr) {
uint8_t *pdata;
dev = m_inputVideoDev;
uint8_t *pdata_user_space = nullptr;

#ifdef TIME_PROFILING
steady_clock::time_point wfb_t0 = steady_clock::now();
#endif
status = waitForBufferPrivate(dev);
#ifdef TIME_PROFILING
steady_clock::time_point wfb_t1 = steady_clock::now();
#endif
if (status != Status::OK) {
return status;
}
Expand All @@ -232,13 +247,22 @@ aditof::Status BufferProcessor::processBuffer(uint16_t *buffer = nullptr) {
return status;
}

#ifdef TIME_PROFILING
steady_clock::time_point mc_t0 = steady_clock::now();
#endif
pdata_user_space = (uint8_t *)malloc(sizeof(uint8_t) * buf_data_len);
memcpy(pdata_user_space, pdata, buf_data_len);
#ifdef TIME_PROFILING
steady_clock::time_point mc_t1 = steady_clock::now();
#endif

uint16_t *tempDepthFrame = m_tofiComputeContext->p_depth_frame;
uint16_t *tempAbFrame = m_tofiComputeContext->p_ab_frame;
float *tempConfFrame = m_tofiComputeContext->p_conf_frame;

#ifdef TIME_PROFILING
steady_clock::time_point tc_t0 = steady_clock::now();
#endif
if (buffer != nullptr) {
m_tofiComputeContext->p_depth_frame = buffer;
m_tofiComputeContext->p_ab_frame =
Expand Down Expand Up @@ -274,6 +298,9 @@ aditof::Status BufferProcessor::processBuffer(uint16_t *buffer = nullptr) {
::write(m_outputVideoDev->fd, m_processedBuffer,
m_outputFrameWidth * m_outputFrameHeight);
}
#ifdef TIME_PROFILING
steady_clock::time_point tc_t1 = steady_clock::now();
#endif

m_tofiComputeContext->p_depth_frame = tempDepthFrame;
m_tofiComputeContext->p_ab_frame = tempAbFrame;
Expand All @@ -287,6 +314,58 @@ aditof::Status BufferProcessor::processBuffer(uint16_t *buffer = nullptr) {
return status;
}

#ifdef TIME_PROFILING
steady_clock::time_point pb_t1 = steady_clock::now();
#endif

#ifdef TIME_PROFILING
// Measure execution times, display statistics
auto process_buffer_elapsed_time =
std::chrono::duration_cast<std::chrono::microseconds>(pb_t1 - pb_t0);
auto wait_for_buffer_elapsed_time =
std::chrono::duration_cast<std::chrono::microseconds>(wfb_t1 - wfb_t0);
auto tofi_compute_elapsed_time =
std::chrono::duration_cast<std::chrono::microseconds>(tc_t1 - tc_t0);
auto frame_memcpy_elapsed_time =
std::chrono::duration_cast<std::chrono::microseconds>(mc_t1 - mc_t0);

auto total_profiled_time = wait_for_buffer_elapsed_time +
tofi_compute_elapsed_time +
frame_memcpy_elapsed_time;

std::cout << std::endl;
std::cout << "BufferProcessor::processBuffer() took: "
<< process_buffer_elapsed_time.count() << "us" << std::endl;
std::cout << "|--> WaitForBuffer() took: "
<< wait_for_buffer_elapsed_time.count() << "us"
<< "("
<< ((double)wait_for_buffer_elapsed_time.count() /
process_buffer_elapsed_time.count()) *
100.0
<< "%)" << std::endl;
std::cout << "|--> TofiCompute() took: "
<< tofi_compute_elapsed_time.count() << "us"
<< "("
<< ((double)tofi_compute_elapsed_time.count() /
process_buffer_elapsed_time.count()) *
100.0
<< "%)" << std::endl;
std::cout << "|--> Frame memcpy() took: "
<< frame_memcpy_elapsed_time.count() << "us"
<< "("
<< ((double)frame_memcpy_elapsed_time.count() /
process_buffer_elapsed_time.count()) *
100.0
<< "%)" << std::endl;
std::cout << "Total profiled time: " << total_profiled_time.count() << "us"
<< "("
<< ((double)total_profiled_time.count() /
process_buffer_elapsed_time.count()) *
100.0
<< "%)" << std::endl;
std::cout << std::endl;
#endif

return status;
}

Expand Down