Add Duration_ns field to kernel trace CSV output

ihhethan · ihhethan · commit 0d2307e3b2b6 · 2025-12-03T15:58:05.000-06:00
Fixes: SWDEV-561821

This change adds the missing Duration_ns field to kernel trace CSV output,
addressing a regression from rocprof to rocprofv3.

Problem:
rocprofv3 --kernel-trace only provides timestamps for each kernel invocation,
unlike the CSV output from rocprof --stats which contained durations.
This is critical for applications like HemeLB where the same hotspot kernel
is called twice per iteration with different durations.

Solution:
Added Duration_ns field (calculated as end - start) to all trace CSV outputs.

Changes:
1. Python (rocpd/csv.py):
   - Added (end - start) AS Duration_ns to 6 trace functions:
     * write_kernel_csv
     * write_memory_copy_csv
     * write_memory_allocation_csv
     * write_counters_csv
     * write_scratch_memory_csv
     * write_region_csv
   - Ensured the column name uses the consistent "Duration_NS" spelling.

2. C++ (generateCSV.cpp):
   - Added \"Duration_ns\" to CSV header
   - Added (record.end_timestamp - record.start_timestamp) as the value
     for the Duration_NS column in kernel trace rows.

3. C++ (csv.hpp):
   - Updated kernel_trace_with_stream_csv_encoder from csv_encoder&lt;22&gt;
     to csv_encoder&lt;23&gt; to account for the new Duration_NS column.

4. Tests (rocprofv3 integration):
   - Added a new test under tests/rocprofv3/kernel-duration-ns:
     * rocprofv3-test-kernel-duration-ns-execute
       - Runs `rocprofv3 --kernel-trace -f csv` on the simple-transpose
         test application to generate out_kernel_trace.csv.
     * rocprofv3-test-kernel-duration-ns-validation
       - Runs validate.py with --csv-input=&lt;out_kernel_trace.csv&gt; and:
         - Asserts that Start_Timestamp, End_Timestamp, and Duration_NS
           columns exist in the header.
         - Verifies that Duration_NS == End_Timestamp - Start_Timestamp
           for multiple rows.

Testing:
- Environment: MI300X, ROCm 6.4.1, Docker container
- Test application: HPCTrainingExamples/daxpy_5
- Verified Duration_ns field appears in column 12
- Verified Duration_ns = End_Timestamp - Start_Timestamp
- Sample values: 80360 ns, 63895 ns, 54680 ns
- New tests:
  * ctest -R "kernel-duration-ns" -V
    - rocprofv3-test-kernel-duration-ns-execute
    - rocprofv3-test-kernel-duration-ns-validation
  * Both tests pass locally.

Impact:
- Restores functionality from legacy rocprof tool
- Enables efficient per-invocation kernel duration analysis
- No breaking changes to existing CSV format
- Backward compatible
diff --git a/projects/rocprofiler-sdk/source/lib/output/csv.hpp b/projects/rocprofiler-sdk/source/lib/output/csv.hpp
@@ -109,7 +109,7 @@ using list_derived_metrics_csv_encoder     = csv_encoder<5>;
 using scratch_memory_encoder               = csv_encoder<9>;
 using stats_csv_encoder                    = csv_encoder<8>;
 using pc_sampling_host_trap_csv_encoder    = csv_encoder<6>;
-using kernel_trace_with_stream_csv_encoder = csv_encoder<22>;
+using kernel_trace_with_stream_csv_encoder = csv_encoder<23>;
 using memory_copy_with_stream_csv_encoder  = csv_encoder<8>;
 using pc_sampling_stochastic_csv_encoder   = csv_encoder<10>;
 }  // namespace csv
diff --git a/projects/rocprofiler-sdk/source/lib/output/generateCSV.cpp b/projects/rocprofiler-sdk/source/lib/output/generateCSV.cpp
@@ -260,31 +260,16 @@ generate_csv(const output_config&
 
     if(cfg.stats && stats)
         write_stats(get_stats_output_file(cfg, domain_type::KERNEL_DISPATCH), stats.entries);
-    auto ofs = tool::csv_output_file{cfg,
-                                     domain_type::KERNEL_DISPATCH,
-                                     tool::csv::kernel_trace_with_stream_csv_encoder{},
-                                     {"Kind",
-                                      "Agent_Id",
-                                      "Queue_Id",
-                                      "Stream_Id",
-                                      "Thread_Id",
-                                      "Dispatch_Id",
-                                      "Kernel_Id",
-                                      "Kernel_Name",
-                                      "Correlation_Id",
-                                      "Start_Timestamp",
-                                      "End_Timestamp",
-                                      "LDS_Block_Size",
-                                      "Scratch_Size",
-                                      "VGPR_Count",
-                                      "Accum_VGPR_Count",
-                                      "SGPR_Count",
-                                      "Workgroup_Size_X",
-                                      "Workgroup_Size_Y",
-                                      "Workgroup_Size_Z",
-                                      "Grid_Size_X",
-                                      "Grid_Size_Y",
-                                      "Grid_Size_Z"}};
+    auto ofs = tool::csv_output_file{
+        cfg,
+        domain_type::KERNEL_DISPATCH,
+        tool::csv::kernel_trace_with_stream_csv_encoder{},
+        {"Kind",           "Agent_Id",         "Queue_Id",         "Stream_Id",
+         "Thread_Id",      "Dispatch_Id",      "Kernel_Id",        "Kernel_Name",
+         "Correlation_Id", "Start_Timestamp",  "End_Timestamp",    "Duration_NS",
+         "LDS_Block_Size", "Scratch_Size",     "VGPR_Count",       "Accum_VGPR_Count",
+         "SGPR_Count",     "Workgroup_Size_X", "Workgroup_Size_Y", "Workgroup_Size_Z",
+         "Grid_Size_X",    "Grid_Size_Y",      "Grid_Size_Z"}};
 
     for(auto ditr : data)
     {
@@ -313,6 +298,7 @@ generate_csv(const output_config&
                 record.correlation_id.internal,
                 record.start_timestamp,
                 record.end_timestamp,
+                (record.end_timestamp - record.start_timestamp),
                 lds_block_size_v,
                 record.dispatch_info.private_segment_size,
                 kernel_info->arch_vgpr_count,
diff --git a/projects/rocprofiler-sdk/source/lib/python/rocpd/csv.py b/projects/rocprofiler-sdk/source/lib/python/rocpd/csv.py
@@ -236,6 +236,7 @@ def write_kernel_csv(importData, config) -> None:
         "stack_id AS Correlation_Id",
         "start AS Start_Timestamp",
         "end AS End_Timestamp",
+        "(end - start) AS Duration_NS",
         "lds_size AS Lds_Block_Size",
         "scratch_size",
         "vgpr_count",
@@ -280,7 +281,8 @@ def write_memory_copy_csv(importData, config) -> None:
             {dst_agent_id} AS Destination_Agent_Id,
             stack_id AS Correlation_Id,
             start AS Start_Timestamp,
-            end AS End_Timestamp
+            end AS End_Timestamp,
+            (end - start) AS Duration_NS
         FROM "memory_copies"
         ORDER BY
             guid ASC, start ASC, end DESC
@@ -310,7 +312,8 @@ def write_memory_allocation_csv(importData, config) -> None:
             '0x' || printf('%016X', address) AS Address,
             stack_id AS Correlation_Id,
             start AS Start_Timestamp,
-            end AS End_Timestamp
+            end AS End_Timestamp,
+            (end - start) AS Duration_NS
         FROM "memory_allocations"
         ORDER BY
             guid ASC, start ASC, end DESC
@@ -343,6 +346,7 @@ def write_counters_csv(importData, config) -> None:
         "value AS Counter_Value",
         "start AS Start_Timestamp",
         "end AS End_Timestamp",
+        "(end - start) AS Duration_NS",
     ]
 
     aliased_headers = []
@@ -375,7 +379,8 @@ def write_scratch_memory_csv(importData, config) -> None:
             tid AS Thread_Id,
             alloc_flags,
             start AS Start_Timestamp,
-            end AS End_Timestamp
+            end AS End_Timestamp,
+            (end - start) AS Duration_NS
         FROM "scratch_memory"
         ORDER BY
             guid ASC, start ASC, end DESC
@@ -394,7 +399,8 @@ def write_region_csv(importData, config) -> None:
             tid AS Thread_Id,
             stack_id AS Correlation_Id,
             start AS Start_Timestamp,
-            end AS End_Timestamp
+            end AS End_Timestamp,
+            (end - start) AS Duration_NS
         FROM "regions"
         ORDER BY
             guid ASC, start ASC, end DESC
diff --git a/projects/rocprofiler-sdk/tests/rocprofv3/CMakeLists.txt b/projects/rocprofiler-sdk/tests/rocprofv3/CMakeLists.txt
@@ -48,6 +48,7 @@ add_subdirectory(conversion-script)
 add_subdirectory(python-bindings)
 add_subdirectory(rocpd)
 add_subdirectory(rocpd-kernel-rename)
+add_subdirectory(kernel-duration-ns)
 add_subdirectory(attachment)
 add_subdirectory(rocpd-scratch)
 add_subdirectory(att-consecutive-kernels)
diff --git a/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/CMakeLists.txt b/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/CMakeLists.txt
@@ -0,0 +1,59 @@
+#
+# rocprofv3 tool tests for kernel duration ns
+#
+cmake_minimum_required(VERSION 3.21.0 FATAL_ERROR)
+
+project(
+    rocprofiler-sdk-tests-rocprofv3-kernel-duration-ns
+    LANGUAGES CXX
+    VERSION 0.0.0)
+
+find_package(rocprofiler-sdk REQUIRED)
+find_package(Python3 REQUIRED)
+
+set(rocprofv3-env
+    "${ROCPROFILER_MEMCHECK_PRELOAD_ENV}"
+    "PYTHONPATH=${rocprofiler-sdk_LIB_DIR}/python${Python3_VERSION_MAJOR}.${Python3_VERSION_MINOR}/site-packages"
+    )
+
+rocprofiler_configure_pytest_files(CONFIG pytest.ini COPY conftest.py validate.py)
+
+add_test(
+    NAME rocprofv3-test-kernel-duration-ns-execute
+    COMMAND
+        $<TARGET_FILE:rocprofiler-sdk::rocprofv3> -d
+        ${CMAKE_CURRENT_BINARY_DIR}/kernel-duration-ns -o out --output-format csv
+        --kernel-trace -- $<TARGET_FILE:simple-transpose>)
+
+set_tests_properties(
+    rocprofv3-test-kernel-duration-ns-execute
+    PROPERTIES TIMEOUT
+               120
+               LABELS
+               "integration-tests;kernel-duration-ns"
+               ENVIRONMENT
+               "${rocprofv3-env}"
+               FAIL_REGULAR_EXPRESSION
+               "${ROCPROFILER_DEFAULT_FAIL_REGEX}"
+               FIXTURES_SETUP
+               rocprofv3-test-kernel-duration-ns-run)
+
+add_test(
+    NAME rocprofv3-test-kernel-duration-ns-validation
+    COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_BINARY_DIR}/validate.py --csv-input
+            ${CMAKE_CURRENT_BINARY_DIR}/kernel-duration-ns/out_kernel_trace.csv)
+
+set_tests_properties(
+    rocprofv3-test-kernel-duration-ns-validation
+    PROPERTIES TIMEOUT
+               120
+               LABELS
+               "integration-tests;kernel-duration-ns"
+               ENVIRONMENT
+               "${rocprofv3-env}"
+               DEPENDS
+               "rocprofv3-test-kernel-duration-ns-execute"
+               FAIL_REGULAR_EXPRESSION
+               "${ROCPROFILER_DEFAULT_FAIL_REGEX}"
+               FIXTURES_REQUIRED
+               rocprofv3-test-kernel-duration-ns-run)
diff --git a/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/conftest.py b/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/conftest.py
@@ -0,0 +1,64 @@
+#!/usr/bin/env python3
+
+# MIT License
+#
+# Copyright (c) 2024-2025 Advanced Micro Devices,
+# Inc. All rights reserved.
+#
+# Permission is hereby granted, free of charge, to any person obtaining a copy
+# of this software and associated documentation files (the "Software"), to deal
+# in the Software without restriction, including without limitation the rights
+# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+# copies of the Software, and to permit persons to whom the Software is
+# furnished to do so, subject to the following conditions:
+#
+# The above copyright notice and this permission notice shall be included in
+# all copies or substantial portions of the Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+# THE SOFTWARE.
+
+import csv
+import os
+from pathlib import Path
+
+import pytest
+
+
+def pytest_addoption(parser):
+    """Register command-line options for this test module."""
+    parser.addoption(
+        "--csv-input",
+        action="store",
+        help="Path to kernel trace CSV file to validate.",
+    )
+
+
+@pytest.fixture
+def csv_path(request) -> Path:
+    """Return the path to the kernel trace CSV file passed via --csv-input."""
+    filename = request.config.getoption("--csv-input")
+    if not filename:
+        raise RuntimeError("--csv-input option is required for this test")
+    path = Path(filename)
+    if not path.is_file():
+        raise FileNotFoundError(f"{path} does not exist")
+    return path
+
+
+@pytest.fixture
+def csv_rows(csv_path: Path):
+    """Yield all rows from the kernel trace CSV as a list of dicts."""
+    rows = []
+    with csv_path.open("r", newline="") as inp:
+        reader = csv.DictReader(inp)
+        for row in reader:
+            rows.append(row)
+    if not rows:
+        raise RuntimeError(f"No data rows found in {csv_path}")
+    return rows
diff --git a/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/pytest.ini b/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/pytest.ini
@@ -0,0 +1,4 @@
+[pytest]
+addopts = --durations=20 -rA -s -vv
+testpaths = validate.py
+pythonpath = @ROCPROFILER_SDK_TESTS_BINARY_DIR@/pytest-packages
diff --git a/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/validate.py b/projects/rocprofiler-sdk/tests/rocprofv3/kernel-duration-ns/validate.py
@@ -0,0 +1,72 @@
+#!/usr/bin/env python3
+
+import argparse
+import csv
+from pathlib import Path
+
+
+def parse_args():
+    parser = argparse.ArgumentParser()
+    parser.add_argument(
+        "--csv-input",
+        type=Path,
+        required=True,
+        help="Path to the generated kernel_trace CSV",
+    )
+    return parser.parse_args()
+
+
+def main():
+    args = parse_args()
+    csv_path: Path = args.csv_input
+
+    if not csv_path.is_file():
+        raise FileNotFoundError(f"CSV file not found: {csv_path}")
+
+    with csv_path.open("r", newline="") as f:
+        reader = csv.reader(f)
+        header = next(reader, None)
+        if header is None:
+            raise RuntimeError("CSV has no header row")
+
+        # Build a mapping from column name to index
+        col_idx = {name: i for i, name in enumerate(header)}
+
+        required_cols = ["Start_Timestamp", "End_Timestamp", "Duration_NS"]
+        missing = [c for c in required_cols if c not in col_idx]
+        if missing:
+            raise RuntimeError(f"Missing required columns: {missing}")
+
+        s_idx = col_idx["Start_Timestamp"]
+        e_idx = col_idx["End_Timestamp"]
+        d_idx = col_idx["Duration_NS"]
+
+        # Only check the first few rows to avoid processing very large files
+        checked_rows = 0
+        for row in reader:
+            if not row:
+                continue
+
+            start = int(row[s_idx])
+            end = int(row[e_idx])
+            duration = int(row[d_idx])
+            calc = end - start
+
+            if duration != calc:
+                raise RuntimeError(
+                    f"Duration_NS mismatch: got {duration}, expected {calc} "
+                    f"(start={start}, end={end})"
+                )
+
+            checked_rows += 1
+            if checked_rows >= 5:
+                break
+
+        if checked_rows == 0:
+            raise RuntimeError("No data rows found to validate Duration_NS")
+
+    print(f"[OK] Validated Duration_NS for {checked_rows} row(s) in {csv_path}")
+
+
+if __name__ == "__main__":
+    main()
