8. Hardware profiling

8.1. Required files

SpaceStudio Project

8.2. Goal

The aim of this tutorial is to answer a question every designer eventually asks about an accelerator that is not going fast enough: where does the time actually go inside my hardware IP? The useful answer is not a waveform, it is a budget expressed in the terms the application is written in: how many milliseconds of each frame are spent moving data in and out of memory, and how many are spent computing.

The usual instrument for looking inside an FPGA design is a logic analyzer such as the Xilinx ILA. It is a signal-level scope: it captures waveforms into a limited on-chip buffer on a trigger condition, and the designer reads the answer off the timing diagram, then maps those cycles back to the line of application code that produced them. That is the right tool for functional bring-up, but it is a long way from “how long did my DDR reads take this frame?”.

SpaceStudio’s Clkctr (clock counter) sits one level above. The user places two timestamps at two points in the application source, subtracts them, and obtains an elapsed time — through the same API whether the code runs on the CPU or in HLS-generated hardware. There is no probe to insert, no waveform to read, and no mapping from signals back to the algorithm.

By the end of this tutorial, the attendee will have instrumented a Sobel filter running on FPGA fabric, obtained a per-instance breakdown of communication versus computation time on the console, and used it to identify what limits the acceleration of the application.

Note

This tutorial assumes you are comfortable with module groups, covered in Tutorial 3, and with running a design on a board through FPGA-in-the-loop, covered in Tutorial 4.

8.3. Application

The tutorial is based on an edge detection application using the Sobel filter, which performs two 3x3 convolutions [1]. The application takes a grayscale image as input and applies the filter to the entire image for a fixed number of times, allowing to compute an average execution time of the algorithm. The resulting output image can be obtained after execution, Figure 8.1 shows an example of the input and output images.

Figure 8.1 Input image (left) and output image (right) of an application execution

The input image can be seen or modified in the imports/images directory inside the SpaceStudio project location, and must be named image_in.pgm. If a new image is used, its dimensions must be set inside application_definitions.h. The image width must be a multiple of four times the slice count.

The application uses the binary PGM image file format (P5) [2]. These images can be viewed or converted to other formats using GIMP or the ImageMagick command-line tool.

8.3.1. Application architecture

he tutorial project runs on a Zynq-7000 SoC and contains two application components :

• Controller: A single instance of this module runs in software on the SoC CPU. It reads and verifies the input image, writes the data to the board’s DDR memory, and triggers the Sobel instances for a configurable number of iterations. Once processing is complete, it formats and outputs the result image. The controller also measures the average execution time of the iterations using the std::chrono API.

• Sobel: Runs in hardware and applies the Sobel filter on a slice of the image. It reads the data and writes its output in the DDR memory. Multiple instances of this module can run in parallel, each processing a separate slice. The image is automatically sliced and distributed based on the number of instantiated Sobel modules.

Figure 8.2 shows a diagram of the application architecture.

Figure 8.2 Diagram of the application architecture

Note

The memory architecture of the Sobel module is optimized to maximize throughput. Details of the different optimizations are outside of the scope of this tutorial, refer to [3] for more details.

8.3.2. Time monitoring needs

Adding Sobel instances accelerates the application, but every instance costs fabric and they all share one path to the DDR, so the instance count cannot be raised indefinitely and the return on each additional one is not guaranteed to stay the same. Deciding how far to take it means knowing what an instance spends its time on.

The execution of a Sobel module is mostly divided between data transfer and processing. Monitoring the time spent in each part is needed to identify the one causing the bottleneck, and make informed decisions about the final architecture. However, the standard std::chrono API is only available for software modules, with no equivalent abstraction for hardware execution. This limitation motivated the development of SpaceStudio’s Chrono API, specifically the Clkctrs, to enable uniform timing measurements across software and hardware components.

Note

This tutorial uses 4 Sobel instances, which is what comfortably fits on the Zedboard it targets. Larger platforms can be used to explore the architecture further.

8.4. Clkctrs

8.4.1. Concept

The Clkctr API allows a module to get the current time efficiently and uniformly whether in software or in HLS generated hardware. Under the hood, the API generates a hardware counter IP if it’s called from a hardware module. When called from software, it uses the OS time similarly to how the std::chrono API works.

The Clkctr API uses the concept of clock domains and extends it to software. It can either be a real hardware clock domain or an operating system, each OS of an application is considered a separate clock domain. When using a Clkctr, the user must specify the target clock domain, as each domain has its own internal time.

8.4.2. Use cases

Currently, the API supports three use cases:

• A software module gets the time of a software module, itself or a different one.

• A software module gets the time of a hardware module.

• A hardware module gets its own time.

8.4.3. Usage

Access to the Clkctr API is via the SPACE_CLKCTR_HANDLE macro:

SPACE_CLKCTR_HANDLE(calling_module, calling_idx, calling_thread,
                        SPACE_ID(target_module, target_idx), clk_variable);

Where :

• module, calling_idx and thread are the module name, index and thread name of the module thread asking for the clock.

• target_module and target_idx are the module name and index of the module instance whose clock domain is tracked.

• clk_variable is the name of the variable storing the clock.

With the clock variable defined, a module can get the current time point with the .now() method. It returns a time object: a counter value, held in a uint64_t, representing the number of ticks elapsed since the epoch of the target clock domain — clock cycles for a hardware domain, OS ticks for a software one.

That time type is nested inside the clock handle, so each handle defines its own. This is what makes the type name unwieldy, and using the auto keyword avoids having to spell it out. It also means time points coming from two different handles are of two different types, so the compiler rejects any attempt to mix them — subtracting a hardware time point from a software one is a meaningless operation, and it is caught at compile time rather than producing a wrong number.

// The thread 'thread' of the 'producer' of index 'INDEX' declares a 'consclk'
// variable tracking the clock domain of the 'consumer' of index 'INDEX'.
SPACE_CLKCTR_HANDLE(producer, INDEX, thread, SPACE_ID(consumer, INDEX), consclk);
// ...
const auto start = consclk.now();
do_something();
const auto end = consclk.now();

Subtracting two time points yields another time object holding the elapsed number of ticks. Note that, unlike the std::chrono API, the Clkctr API uses a single type for a time point and for a duration. The elapsed time is then converted to a usable value using one of two methods :

1. .to_sec<type>() returns the number of seconds elapsed in the specified type. It is currently only available for software clocks.

2. .jiffies() returns the number of ticks elapsed. In hardware, this corresponds to the number of clock cycles and can be converted to time units using the module clock frequency.

#if MAPPING = SW_MAPPING

    float elapsed_sec = (end - start).to_sec<float>(); //Only available to software

#else //HW_MAPPING

    uint32_t hw_frequency = 100e6;
    uint64_t elapsed_ticks = (end - start).jiffies();
    float elapsed_sec = static_cast<float>(elapsed_ticks) /
                        static_cast<float>(hw_frequency);

#endif

Note

Documentation for SpaceStudio’s chrono API can be found in the Clock counters section.

8.5. Manipulations

The following manipulations show the three Clkctrs use cases applied to the Sobel Operator application, and how to get time profiling of the hardware Sobel modules execution.

8.5.1. Create a new solution

Start from the provided SpaceStudio project and create a new solution based on the existing one. Remove the lines used to track time in controller.cpp (i.e., the std::chrono include and all lines referring to the chrono API or the execution_time variable).

8.5.2. Include Spacestudio’s Chrono API

In controller.cpp and sobel.cpp, add:

#include "space_chrono.h"

8.5.3. Use case 1: Software module reads a software clock

At the start of the thread method inside controller.cpp, declare a software Clkctr tracking the Controller instance :

SPACE_CLKCTR_HANDLE(controller, INDEX, thread,
                        SPACE_ID(controller, INDEX), controller_clk);

This can be then used to track the time spent waiting for the Sobel instances execution :

double cumul_sw_execution_time = 0;

//…

for (int i = 0; i < NUM_ITERATIONS; i++) {

    const auto sobel_start_sw = controller_clk.now();

    // Notify sobel modules to start working
    //…

    // Wait for sobel modules to complete
    //…

    const auto sobel_end_sw = controller_clk.now();
    cumul_sw_execution_time += (sobel_end_sw - sobel_start_sw).to_sec<double>();
}

8.5.4. Use case 2: Software module reads a hardware clock

Still in controller.cpp, declare a hardware Clkctr tracking the clock domain of the first Sobel instance. As all Sobel instances share the same clock domain, this clock tracks the parallel execution of all hardware instances.

SPACE_CLKCTR_HANDLE(controller, INDEX, thread, SPACE_ID(sobel, 0), sobel_clk);

It can be used in the same way as the software Clkctr from the previous manipulation. In this case the actual clock cycle number is measured with a hardware counter IP :

double cumul_sw_execution_time = 0;
double cumul_hw_execution_time = 0;

//…

for (int i = 0; i < NUM_ITERATIONS; i++) {

    const auto sobel_start_sw = controller_clk.now();
    const auto sobel_start_hw = sobel_clk.now();

    // Notify sobel modules to start working
    //…

    // Wait for sobel modules to complete
    //…

    const auto sobel_end_sw = controller_clk.now();
    const auto sobel_end_hw = sobel_clk.now();

    cumul_sw_execution_time += (sobel_end_sw - sobel_start_sw).to_sec<double>();
    cumul_hw_execution_time +=
        static_cast<double>((sobel_end_hw - sobel_start_hw).jiffies()) / HW_FREQUENCY;
}

8.5.5. Use case 3: Hardware module reads its own hardware clock

This is the most useful case for this application. It allows to measure the time of the different execution parts inside the Sobel hardware instances and send them explicitly to the software Controller. At the start of the thread method inside sobel.cpp, declare the Clkctr :

SPACE_CLKCTR_HANDLE(sobel, INDEX, thread, SPACE_ID(sobel, INDEX), clk);

As every Sobel module instance shares the same clock domain, all instances are able to read time from a single hardware counter.

The communication time can now be determined from the duration of all DDR DeviceRead() and DeviceWrite() uses, for example :

uint64_t communication_time = 0;

auto start_communication_time = clk.now();

DeviceWrite(...);

auto end_communication_time = clk.now();
communication_time += (end_communication_time - start_communication_time).jiffies();

And the time of actual computation can be determined in a similar way :

uint64_t computation_time = 0;

//…

// Perform Sobel line per line
for (unsigned int line = 1; line < img_height-1; ++line) {

    auto start_computation_time = clk.now();

    // Instantiate the window for the first pixel of the line
    //…

    // Compute the operator for each pixel of the line
    //…

    auto end_computation_time = clk.now();
    computation_time += (end_computation_time - start_computation_time).jiffies();

    // Write the output line
    //…

    // Read the next line
    //…
}

Finally, measure the complete execution time seen from the Sobel hardware instance :

uint64_t total_time = 0;

// Wait for the controller notification
StreamRead(CONTROLLER0_ID, SPACE_BLOCKING);

auto start_total_time = clk.now();
//…

auto end_total_time = clk.now();
total_time += (end_total_time - start_total_time).jiffies();

// Notify controller we are done
StreamWrite(CONTROLLER0_ID, SPACE_BLOCKING);

These measurements can be transferred explicitly to the controller for formatting and printing. At the end of the sobel.cpp thread, add :

// Send timing data to controller
StreamWrite(CONTROLLER0_ID, SPACE_BLOCKING, communication_time);
StreamWrite(CONTROLLER0_ID, SPACE_BLOCKING, computation_time);
StreamWrite(CONTROLLER0_ID, SPACE_BLOCKING, total_time);

Then inside controller.cpp, declare a new array storing the measurements from all Sobel instances:

double cumul_sobel_clock_data[SOBEL_GROUP_SIZE][3] = {0};

And add code to receive and store the measurements in seconds at the end of Controller’s execution:

uint64_t communication_time; // holds sobel communication time (in clock cycles)
uint64_t computation_time;   // holds sobel computation time (in clock cycles)
uint64_t total_time;         // holds sobel total execution time (in clock cycles)

// Get Clkctr data measured inside the hardware modules
for (unsigned int index = 0; index < SOBEL_GROUP_SIZE; ++index) {

    StreamRead(SOBEL_GROUP[index], SPACE_BLOCKING, communication_time);
    StreamRead(SOBEL_GROUP[index], SPACE_BLOCKING, computation_time);
    StreamRead(SOBEL_GROUP[index], SPACE_BLOCKING, total_time);

    cumul_sobel_clock_data[index][0] += static_cast<double>(communication_time) / HW_FREQUENCY;
    cumul_sobel_clock_data[index][1] += static_cast<double>(computation_time) / HW_FREQUENCY;
    cumul_sobel_clock_data[index][2] += static_cast<double>(total_time) / HW_FREQUENCY;
}

8.5.6. Add a detailed print

The print_results() method inside controller.cpp needs an update to output the new measurements:

void controller::print_results(double cumul_sw_time, double cumul_hw_time, double cumul_sobel_clock_data[SOBEL_GROUP_SIZE][3]) {

    const double sw_avg = cumul_sw_time/NUM_ITERATIONS;
    const double hw_avg = cumul_hw_time/NUM_ITERATIONS;

    printf("\n======= Sobel Performance Summary (%d slices, %d iterations avg) =======\n\n", SOBEL_GROUP_SIZE, NUM_ITERATIONS);

    printf("Clkctr case 1 (controller, software clock) : %8.3f ms  (%6.2f FPS)\n", sw_avg*1e3, 1.0/sw_avg);
    printf("Clkctr case 2 (controller, sobel clock)    : %8.3f ms  (%6.2f FPS)\n\n", hw_avg*1e3, 1.0/hw_avg);

    printf("Clkctr case 3 (measured inside each sobel instance) :\n\n");

    printf("Module |  Comm [ms] |  Comp [ms] | Total [ms] | Comm %% | Comp %% |    FPS\n");
    printf("-------+------------+------------+------------+--------+--------+-------\n");

    double cumul_comm_share = 0;
    double cumul_comp_share = 0;

    for (unsigned int index = 0; index < SOBEL_GROUP_SIZE; ++index) {

            const double comm = cumul_sobel_clock_data[index][0]/NUM_ITERATIONS;
            const double comp = cumul_sobel_clock_data[index][1]/NUM_ITERATIONS;
            const double total = cumul_sobel_clock_data[index][2]/NUM_ITERATIONS;

            printf("%6u | %10.3f | %10.3f | %10.3f | %5.1f%% | %5.1f%% | %6.2f\n",
                            index, comm*1e3, comp*1e3, total*1e3,
                            100.0*comm/total, 100.0*comp/total, 1.0/total);

            cumul_comm_share += 100.0*comm/total;
            cumul_comp_share += 100.0*comp/total;
    }

    printf("\nAverage share of communication in total time : %.1f %%\n", cumul_comm_share/SOBEL_GROUP_SIZE);
    printf("Average share of computation   in total time : %.1f %%\n", cumul_comp_share/SOBEL_GROUP_SIZE);

    printf("\n========================================================================\n");
}

Finally, don’t forget to update the method declaration inside controller.h :

void print_results(double sw_time, double hw_time,
                   double sobel_clock_data[SOBEL_GROUP_SIZE][3]);

8.6. Results

Running the application with 4 Sobel instances and the newly added Clkctrs results in the following output:

======= Sobel Performance Summary (4 slices, 100 iterations avg) =======

Clkctr case 1 (controller, software clock) :   13.253 ms  ( 75.45 FPS)
Clkctr case 2 (controller, sobel clock)    :   13.253 ms  ( 75.45 FPS)

Clkctr case 3 (measured inside each sobel instance) :

Module |  Comm [ms] |  Comp [ms] | Total [ms] | Comm % | Comp % |    FPS
-------+------------+------------+------------+--------+--------+-------
     0 |      7.419 |      5.401 |     12.889 |  57.6% |  41.9% |  77.59
     1 |      7.592 |      5.390 |     13.041 |  58.2% |  41.3% |  76.68
     2 |      7.650 |      5.390 |     13.099 |  58.4% |  41.1% |  76.34
     3 |      7.538 |      5.390 |     12.987 |  58.0% |  41.5% |  77.00

Average share of communication in total time : 58.1 %
Average share of computation   in total time : 41.5 %

========================================================================

Communication accounts for 58% of the time each Sobel instance spends on a frame, against 41% for the convolution itself. The DDR accesses, not the filter logic, are what this architecture spends its time on.

8.6.1. Scaling the architecture

Running the same application on the 1_slice architecture and comparing the two gives the return on the added instances:

Sobel instances	Communication	Computation	Total	Comm share	Frame rate
1	23.628 ms	20.924 ms	44.636 ms	52.9 %	22.4 FPS
4	7.550 ms	5.393 ms	13.004 ms	58.1 %	75.5 FPS
speed-up	3.13 x	3.88 x	3.43 x		3.37 x

Computation scales almost perfectly. An instance spends 1.011 clock cycles per pixel on its own and 1.042 with three others running beside it, so quadrupling the instances simply divides the work: the convolution pipeline does not care how many copies of it exist.

Communication does not scale. A byte costs 0.571 cycles to move with one instance and 0.730 with four, and that difference is the whole of the missing speed-up: four instances return 3.37 x instead of 4 x, and the share of the frame spent on DDR traffic climbs from 52.9 % to 58.1 %. The memory path, not the filter logic, is what limits this architecture as instances are added — which is precisely the conclusion no amount of staring at the total execution time could have produced.

Two mechanisms would both explain it, and these two measurements cannot separate them. Each transfer carries 480 bytes with four instances instead of 1920, so any fixed per-transfer cost is amortized over a quarter as much data; at the same time, four masters now arbitrate for the same memory port. Building the 2-instance architecture and reading the same columns tells them apart: if the cost of a transfer is a fixed overhead plus a per-byte rate, the numbers above predict 599 cycles for a 960-byte transfer, and anything appreciably slower is contention. The remedy differs accordingly — fewer and larger transfers in the first case, covered in Tutorial 6, or the memory architecture itself in the second.

Note

On a Zedboard (xc7z020), each Sobel instance costs about 6,000 LUTs, so 4 instances use 46% of the device and 8 instances no longer fit. The LUT budget is what binds here — the same design uses only 27% of the flip-flops, 11% of the block RAM and no DSP at all. Consult the FPGA utilization report of an architecture to see where a given instance count lands, and use a larger platform to explore beyond that point.

8.7. Conclusion

The attendee took an image-processing application accelerated on FPGA fabric, instrumented its hardware modules with a Clkctr, and read off the console where the time actually goes.

The third use case — a hardware module timing its own execution — is the one that answers the question this tutorial opens with. Cases 1 and 2 measure how long the offload takes, but only from the outside: they report a single number and cannot say what it is made of. Three pairs of .now() calls placed around the DeviceRead() and DeviceWrite() sites and around the convolution loop split the 13.0 ms that a Sobel instance spends per frame into 7.55 ms of DDR traffic and 5.39 ms of computation. The measurement is taken per instance, in the module’s own clock cycles, and reaches the software controller as three ordinary values on a stream, where it is formatted and printed like any other application data.

That split is the payoff. At 4 instances, more of each frame goes into moving pixels in and out of the DDR than into the convolution itself — 58% against 41% — so this architecture is dominated by its memory traffic, not by its filter logic. The consequence is directly actionable, and it is not “add more instances”: the LUT budget of the board is nearly half spent at 4, and even if it were not, optimizing the operator could only ever reclaim the smaller share of the two. The lever with the most room is the memory architecture — wider or burst transfers, a different port, or overlapping transfers with computation, as covered in Tutorial 6.

Comparing the two architectures turns that reading into a direction. Quadrupling the instances returns 3.37 x rather than 4 x, and the whole of the shortfall sits in communication: the convolution scales at 97 % of ideal while the transfers manage 78 %, so the share of each frame spent moving data climbs from 52.9 % to 58.1 %. The design is walking towards a memory wall rather than a compute one, and each instance added is worth a little less than the one before it. Where that wall stands exactly, and whether it is built from transfer size or from port contention, is one more architecture away — and it is read from the same two columns.

Reaching that conclusion took three pairs of timestamps in the application source. The equivalent at the signal level means probing the AXI interfaces with a logic analyzer, capturing into a buffer far too shallow to hold a whole frame, and reconstructing the per-region totals from the waveform by hand — for each of the four instances. A Clkctr does not replace a logic analyzer for functional debug, but for the question “where is my hardware IP spending its time?”, asking it in the application’s own terms is both faster and much closer to the decision it informs.

The method generalizes beyond this application. When adding instances stops paying, instrument inside the accelerator before adding more of them: an outside measurement tells you that something is slow, while timing the regions of the hardware thread tells you which part — and only the second one changes what you build next.

8.8. Result files

SpaceStudio Project

8.9. References

[1]

Wikipedia: Sobel operator

[2]

Netpbm: pgm - Netpbm grayscale image format

[3]

AMD: Video Design in the Vivado HLS Tool Application Note (XAPP793)