intel / compute-runtime

Intel® Graphics Compute Runtime for oneAPI Level Zero and OpenCL™ Driver
MIT License
1.1k stars 229 forks source link

Immediate Command Lists - Event Query #668

Open pvelesko opened 11 months ago

pvelesko commented 11 months ago

I have the following simple test case:

#include <iostream>
#include <hip/hip_runtime.h>

// Simple time-consuming kernel without arguments
__global__ void slowKernel() {
    float val = 0.0f;
    for (int i = 0; i < 10000; i++) {
        for (int j = 0; j < 10000; j++) {
            val += sqrtf(val + i + j);
        }
    }
}

int main() {
    float milliseconds = 0;
    hipEvent_t start, stop;
    hipEventCreate(&start);
    hipEventCreate(&stop);

    hipEventRecord(start, 0);

    // Launching the kernel with arbitrary grid and block sizes
    hipLaunchKernelGGL(slowKernel, dim3(512), dim3(256), 0, 0);

    hipEventRecord(stop, 0);

    assert(hipEventElapsedTime(&milliseconds, stop, stop) == hipErrorNotReady);
    assert(hipEventElapsedTime(&milliseconds, start, start) == hipSuccess);
    assert(hipEventElapsedTime(&milliseconds, stop, stop) == hipErrorNotReady);

    hipError_t err = hipEventElapsedTime(&milliseconds, start, stop);

    // Check if elapsed time returns hipErrorNotReady
    if (err == hipErrorNotReady) {
        std::cout << "Kernel still in progress..." << std::endl;
    } else {
        std::cout << "Kernel execution time: " << milliseconds << " ms" << std::endl;
    }

    return 0;
}

This kernel runs for about 3 seconds, and as you can see in the example, I am not doing any explicit synchronization.

Issue: event query on the start event seems to force some sort of synchronization such that the repeated stop event query returns ZE_RESULT_SUCCESS even though the kernel should still be running. If I query the stop event multiple times, it will return ZE_NOT_READY but as soon as I query the start event, the next query to stop event will result in ZE_RESULT_SUCCESS while not ready is expected.

Here's the Level Zero log - please let me know if this is some sort of expected behavior and if not, I can make a pure level zero reproducer.

04:02:30.591052040 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_entry: { hEvent: 0x000055f567cba750 }
04:02:30.591052832 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.591054291 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_entry: { hCommandList: 0x000055f567bbcd40, hSignalEvent: 0x000055f567cba750, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, phWaitEvents_vals: [  ] }
04:02:30.591074529 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695454241346, deviceTimestamp: 62221274031 }
04:02:30.591091138 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567cba750 }
04:02:30.591091509 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.591102221 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventRecord_exit: { hipResult: hipSuccess }
04:02:30.591108914 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:__hipPushCallConfiguration_entry: { gridDim: { x: 512, y: 1, z: 1 }, blockDim: { x: 256, y: 1, z: 1 }, sharedMem: 0, stream: 0x0000000000000000 }
04:02:30.591122005 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:__hipPushCallConfiguration_exit: { hipResult: hipSuccess }
04:02:30.591122849 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:__hipPopCallConfiguration_entry: { gridDim: 0x00007fff36a79050, blockDim: 0x00007fff36a79040, sharedMem: 0x00007fff36a79038, stream: 0x00007fff36a79030 }
04:02:30.591140974 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:__hipPopCallConfiguration_exit: { hipResult: hipSuccess, gridDim_val: { x: 512, y: 1, z: 1 }, blockDim_val: { x: 256, y: 1, z: 1 }, sharedMem_val: 0, stream_val: 0x000055f567bb3af0 }
04:02:30.591141897 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipLaunchKernel_entry: { function_address: 0x000055f56656cd88, numBlocks: { x: 512, y: 1, z: 1 }, dimBlocks: { x: 256, y: 1, z: 1 }, args: 0x00007fff36a79000, sharedMemBytes: 0, stream: 0x000055f567bb3af0 }
04:02:30.591567434 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeModuleCreate_entry: { hContext: 0x000055f567bb2e40, hDevice: 0x000055f567b71650, desc: 0x00007fff36a78670, phModule: 0x000055f567cbaf70, phBuildLog: 0x00007fff36a78638, desc_val: { stype: ZE_STRUCTURE_TYPE_MODULE_DESC, pNext: 0x0000000000000000, format: ZE_MODULE_FORMAT_IL_SPIRV, inputSize: 1032, pInputModule: 0x000055f567cbaa60, pBuildFlags: 0x000055f567c000f0, pConstants: 0x0000000000000000 }, desc__pBuildFlags_val: "-cl-std=CL2.0 -cl-take-global-address -cl-match-sincospi", desc__pConstants_val: , desc__pConstants__pConstantIds_vals: [], desc__pConstants__pConstantValues_vals: [  ] }
04:02:30.655051734 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_build:log: { buildLog: "" }
04:02:30.655056824 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeModuleCreate_exit: { zeResult: ZE_RESULT_SUCCESS, phModule_val: 0x000055f567cbaf80, phBuildLog_val: 0x000055f567cbc1a0 }
04:02:30.655076521 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeModuleGetKernelNames_entry: { hModule: 0x000055f567cbaf80, pCount: 0x00007fff36a77f84, pNames: 0x0000000000000000, pCount_val: 0 }
04:02:30.655077366 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeModuleGetKernelNames_exit: { zeResult: ZE_RESULT_SUCCESS, pCount_val: 1, pNames_vals: [  ] }
04:02:30.655079079 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeModuleGetKernelNames_entry: { hModule: 0x000055f567cbaf80, pCount: 0x00007fff36a77f84, pNames: 0x00007fff36a77910, pCount_val: 1 }
04:02:30.655079259 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeModuleGetKernelNames_exit: { zeResult: ZE_RESULT_SUCCESS, pCount_val: 1, pNames_vals: [ 0x000055f567cff480 ] }
04:02:30.655108509 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelCreate_entry: { hModule: 0x000055f567cbaf80, desc: 0x00007fff36a77bc8, phKernel: 0x00007fff36a77be8, desc_val: { stype: ZE_STRUCTURE_TYPE_KERNEL_DESC, pNext: 0x0000000000000000, flags: [ ZE_KERNEL_FLAG_FORCE_RESIDENCY ], pKernelName: 0x00007fff36a77c18 }, desc__pKernelName_val: "_Z10slowKernelv" }
04:02:30.655112762 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:kernel: { hKernel: 0x000055f567cc8800, pKernelProperties_val: { stype: ZE_STRUCTURE_TYPE_KERNEL_PROPERTIES, pNext: 0x0000000000000000, numKernelArgs: 0, requiredGroupSizeX: 0, requiredGroupSizeY: 0, requiredGroupSizeZ: 0, requiredNumSubGroups: 0, requiredSubgroupSize: 0, maxSubgroupSize: 32, maxNumSubgroups: 32, localMemSize: 0, privateMemSize: 0, spillMemSize: 0, uuid: { kid: 00000000-0000-0000-0000-000000000000, mid: 00000000-0000-0000-0000-000000000000 } } }
04:02:30.655113222 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelCreate_exit: { zeResult: ZE_RESULT_SUCCESS, phKernel_val: 0x000055f567cc8800 }
04:02:30.655123747 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelGetProperties_entry: { hKernel: 0x000055f567cc8800, pKernelProperties: 0x00007fff36a77840 }
04:02:30.655124188 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelGetProperties_exit: { zeResult: ZE_RESULT_SUCCESS, pKernelProperties_val: { stype: ZE_STRUCTURE_TYPE_KERNEL_PROPERTIES, pNext: 0x0000000000000000, numKernelArgs: 0, requiredGroupSizeX: 0, requiredGroupSizeY: 0, requiredGroupSizeZ: 0, requiredNumSubGroups: 0, requiredSubgroupSize: 0, maxSubgroupSize: 32, maxNumSubgroups: 32, localMemSize: 0, privateMemSize: 0, spillMemSize: 0, uuid: { kid: 00000000-0000-0000-0000-000000000000, mid: 00000000-0000-0000-0000-000000000000 } } }
04:02:30.655310473 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_entry: { hEvent: 0x000055f567cba440 }
04:02:30.655312101 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655314433 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_entry: { hCommandList: 0x000055f567bbcd40, hSignalEvent: 0x000055f567cba440, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, phWaitEvents_vals: [  ] }
04:02:30.655377256 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695518540814, deviceTimestamp: 62222508633 }
04:02:30.655415342 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567cba440 }
04:02:30.655415755 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655441070 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_entry: { hEvent: 0x000055f567cba130 }
04:02:30.655441451 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655446633 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelSetGroupSize_entry: { hKernel: 0x000055f567cc8800, groupSizeX: 256, groupSizeY: 1, groupSizeZ: 1 }
04:02:30.655447249 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelSetGroupSize_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655448763 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelSetIndirectAccess_entry: { hKernel: 0x000055f567cc8800, flags: [ ZE_KERNEL_INDIRECT_ACCESS_FLAG_HOST, ZE_KERNEL_INDIRECT_ACCESS_FLAG_DEVICE ] }
04:02:30.655449185 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeKernelSetIndirectAccess_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655451157 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendLaunchKernel_entry: { hCommandList: 0x000055f567bbcd40, hKernel: 0x000055f567cc8800, pLaunchFuncArgs: 0x00007fff36a77ca8, hSignalEvent: 0x000055f567cba130, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, pLaunchFuncArgs_val: { groupCountX: 512, groupCountY: 1, groupCountZ: 1 }, phWaitEvents_vals: [  ] }
04:02:30.655458968 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695518622817, deviceTimestamp: 62222510218 }
04:02:30.655528455 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567cba130 }
04:02:30.655529404 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendLaunchKernel_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655531189 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_entry: { hEvent: 0x000055f567cba130 }
04:02:30.655532433 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_exit: { zeResult: ZE_RESULT_NOT_READY }
04:02:30.655549840 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipLaunchKernel_exit: { hipResult: hipSuccess }

04:02:30.655551041 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventRecord_entry: { event: 0x000055f567b53310, stream: 0x0000000000000000 }
04:02:30.655554477 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeDeviceGetGlobalTimestamps_entry: { hDevice: 0x000055f567b71650, hostTimestamp: 0x000055f567b53398, deviceTimestamp: 0x000055f567b533a0 }
04:02:30.655567979 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeDeviceGetGlobalTimestamps_exit: { zeResult: ZE_RESULT_SUCCESS, hostTimestamp_val: 92695518731605, deviceTimestamp_val: 62222512309 }
04:02:30.655568587 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_entry: { hCommandList: 0x000055f567bbcd40, hSignalEvent: 0x0000000000000000, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, phWaitEvents_vals: [  ] }
04:02:30.655633446 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695518797304, deviceTimestamp: 62222513570 }
04:02:30.655685446 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567d87c10 }
04:02:30.655685700 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655686704 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendWriteGlobalTimestamp_entry: { hCommandList: 0x000055f567bbcd40, dstptr: 0x00007fabc5000000, hSignalEvent: 0x0000000000000000, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, phWaitEvents_vals: [  ] }
04:02:30.655722749 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695518886604, deviceTimestamp: 62222515285 }
04:02:30.655769528 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567cc7ec0 }
04:02:30.655769966 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendWriteGlobalTimestamp_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655770323 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_entry: { hCommandList: 0x000055f567bbcd40, hSignalEvent: 0x0000000000000000, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, phWaitEvents_vals: [  ] }
04:02:30.655806550 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695518970417, deviceTimestamp: 62222516894 }
04:02:30.655850440 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567cc1db0 }
04:02:30.655850649 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655851724 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendMemoryCopy_entry: { hCommandList: 0x000055f567bbcd40, dstptr: 0x000055f567b533b8, srcptr: 0x00007fabc5000000, size: 8, hSignalEvent: 0x000055f567bc8180, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, phWaitEvents_vals: [  ] }
04:02:30.655863499 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695519027352, deviceTimestamp: 62222517985 }
04:02:30.655924379 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567bc8180 }
04:02:30.655924991 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendMemoryCopy_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655927505 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_entry: { hEvent: 0x000055f567cb9e20 }
04:02:30.655927978 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventHostReset_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655929824 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_entry: { hCommandList: 0x000055f567bbcd40, hSignalEvent: 0x000055f567cb9e20, numWaitEvents: 0, phWaitEvents: 0x0000000000000000, phWaitEvents_vals: [  ] }
04:02:30.655937857 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_properties:device_timer: { hDevice: 0x000055f567b71650, hostTimestamp: 92695519101708, deviceTimestamp: 62222519415 }
04:02:30.655939599 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze_profiling:event_profiling: { hEvent: 0x000055f567cb9e20 }
04:02:30.655939691 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeCommandListAppendBarrier_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:30.655941740 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventRecord_exit: { hipResult: hipSuccess }

04:02:30.655944628 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventElapsedTime_entry: { ms: 0x00007fff36a790c8, start: 0x000055f567b53310, stop: 0x000055f567b53310 }
04:02:30.655949235 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_entry: { hEvent: 0x000055f567bc8180 }
04:02:30.655950199 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_exit: { zeResult: ZE_RESULT_NOT_READY }
04:02:30.656205231 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventElapsedTime_exit: { hipResult: hipErrorNotReady, ms_val: 0.0 }
04:02:30.656205632 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventElapsedTime_entry: { ms: 0x00007fff36a790c8, start: 0x000055f567b53170, stop: 0x000055f567b53170 }
04:02:30.656206627 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_entry: { hEvent: 0x000055f567bc77c0 }
04:02:31.010469764 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:31.010473803 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_entry: { hEvent: 0x000055f567bc77c0 }
04:02:31.010474117 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:31.010492243 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventElapsedTime_exit: { hipResult: hipSuccess, ms_val: 0.0 }
04:02:31.010492729 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventElapsedTime_entry: { ms: 0x00007fff36a790c8, start: 0x000055f567b53310, stop: 0x000055f567b53310 }
04:02:31.010493688 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_entry: { hEvent: 0x000055f567bc8180 }
04:02:31.010494362 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:31.010494640 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_entry: { hEvent: 0x000055f567bc8180 }
04:02:31.010494738 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_ze:zeEventQueryStatus_exit: { zeResult: ZE_RESULT_SUCCESS }
04:02:31.010495039 - cupcake - vpid: 512542, vtid: 512542 - lttng_ust_hip:hipEventElapsedTime_exit: { hipResult: hipSuccess, ms_val: 0.0 }