cl::finish does not work on enqueueNDRangeKernel?

Question

I'm trying to profile the performance of my OpenCL Kernel in C++. I currently do this using std::chrono to save the start-time every time before enqueuing anything, calling cl::finish() afterwards and then saving the end-time. While most results look accurate, I get one buffer taking way longer to read than all the other buffers.

If you look into the times i logged in the screenshot below, you'll see that "Next Index" takes much more time than "Vertex", "Normal" or "Tri" (~770ms vs 50-200ms). (These are the 4 read buffers, I enqueue). This is weird because "Vertex" and "Normal" hold floats (which should be at least the same memory as int32?) and are of 1.5 the size, compared to "Next Index" which holds int32s. Especially as "Tri" also hold int32s and only takes 54ms compared to "Next Index"'s 770ms (though to be fair, it's only have the size of "Next Index").

Now I think the reason for this is that the kernels haven't actually executed when logged. As you can see they basically take no ms at all, when they are quite computationally expensive and "Next Index" is the first ReadBuffer so it basically takes all the blame. So I think the problem isn't with "Next Index" but with logging the kernels. I found this: https://community.khronos.org/t/clenqueuereadbuffer-is-incredibly-slow-when-called-infrequently/7325 where the answers state that cl::flush() should be called after "enqueueNDRangeKernel" so the CPU actually waits until the kernels finish (which I thought cl::finish() would do already?) but if I swap "flush" for "finish" I still get the same results.

So does anyone have any idea on how to measue kernel performance in this situation? I could obviously only queue one kernel and a very small read buffer and then just measure after the latter has finished to get the kernel execution time, but I'd like to have a cleaner solution, so I can test whenever I want to, without changing much of the code each time.

Below I also posted the way I queue the kernels and buffers and how I log time:

    // queue Kernel execution, calculate a whole cube per work item
    queue.enqueueNDRangeKernel(marchingCubesKernel, cl::NullRange, cl::NDRange(cubeCount));
    cl::finish();
    auto enqueue1End = std::chrono::high_resolution_clock::now();
    auto enqueue2Start = std::chrono::high_resolution_clock::now();
    // enqueue one kernel per vertex to search for next viable vertex in array
    queue.enqueueNDRangeKernel(cleanUpKernel, cl::NullRange, cl::NDRange(vertexCount));
    cl::finish();
    auto enqueue2End = std::chrono::high_resolution_clock::now();

    auto enqueueReadStart = std::chrono::high_resolution_clock::now();
    // Read buffer back into vectors
    auto nextIndexStart = std::chrono::high_resolution_clock::now();
    queue.enqueueReadBuffer(nextIndexBuf, CL_FALSE, 0, sizeof(int32) * nextIndex.size(), nextIndex.data());
    cl::finish();
    auto nextIndexEnd = std::chrono::high_resolution_clock::now();
    auto vertexStart = std::chrono::high_resolution_clock::now();
    queue.enqueueReadBuffer(vertexBuf, CL_FALSE, 0, sizeof(float) * verCoords.size(), verCoords.data());
    cl::finish();
    auto vertexEnd = std::chrono::high_resolution_clock::now();
    auto normalStart = std::chrono::high_resolution_clock::now();
    queue.enqueueReadBuffer(normalBuf, CL_FALSE, 0, sizeof(float) * verNormalCoords.size(), verNormalCoords.data());
    cl::finish();
    auto normalEnd = std::chrono::high_resolution_clock::now();
    auto triStart = std::chrono::high_resolution_clock::now();
    queue.enqueueReadBuffer(triangleBuf, CL_FALSE, 0, sizeof(int32) * tris.size(), tris.data());
    cl::finish();
    auto triEnd = std::chrono::high_resolution_clock::now();
    // wait till queue is empty
    cl::finish();
    auto enqueueReadEnd = std::chrono::high_resolution_clock::now();

    auto end = std::chrono::high_resolution_clock::now();
    double timeTaken = std::chrono::duration_cast<std::chrono::milliseconds>(end - start).count();
    double kernel1Time = std::chrono::duration_cast<std::chrono::milliseconds>(enqueue1End - enqueue1Start).count();
    double kernel2Time = std::chrono::duration_cast<std::chrono::milliseconds>(enqueue2End - enqueue2Start).count();
    double readTime = std::chrono::duration_cast<std::chrono::milliseconds>(enqueueReadEnd - enqueueReadStart).count();
    UE_LOG(LogTemp, Warning, TEXT("Cube March took: %f ms, consisting of:"), timeTaken);
    UE_LOG(LogTemp, Warning, TEXT("Kernel1 took: %f ms"), kernel1Time);
    UE_LOG(LogTemp, Warning, TEXT("Kernel2 took: %f ms"), kernel2Time);
    UE_LOG(LogTemp, Warning, TEXT("Reading took: %f ms"), readTime);

    double nextIndexTime = std::chrono::duration_cast<std::chrono::milliseconds>(nextIndexEnd - nextIndexStart).count();
    UE_LOG(LogTemp, Warning, TEXT("Next Index took: %f ms"), nextIndexTime);
    double vertexTime = std::chrono::duration_cast<std::chrono::milliseconds>(vertexEnd - vertexStart).count();
    UE_LOG(LogTemp, Warning, TEXT("Vertex Time took: %f ms"), vertexTime);
    double normalTime = std::chrono::duration_cast<std::chrono::milliseconds>(normalEnd - normalStart).count();
    UE_LOG(LogTemp, Warning, TEXT("Normal Time took: %f ms"), normalTime);
    double triTime = std::chrono::duration_cast<std::chrono::milliseconds>(triEnd - triStart).count();
    UE_LOG(LogTemp, Warning, TEXT("Tri Time took: %f ms"), triTime);

If anyone has an idea, please let me know. It's not a big issue but I'd like to understand why finish and flush dont seem to work on kernels. Thanks in advance, foodius

Answer 1

When using cl::finish(); the queue has to be created using makeDefault() or at least method makeDefaultProvided() used to set the current queue as a default one. Otherwise calls to cl::finish(); will do nothing and may return an error too.

Better option is to use queue.finish() so that it's clear on which queue the finish call is executed. Alternatively call to queue.enqueueReadBuffer() can be a blocking one by passing CL_TRUE and then queue.finish() is redundant.