Skip to content

Commit 5c235f0

Browse files
nrspruitnrspruit
committed
Update the tracing of APIs in the validation layer with params
Signed-off-by: Neil R. Spruit <neil.r.spruit@intel.com>
1 parent 2938500 commit 5c235f0

14 files changed

Lines changed: 16212 additions & 2209 deletions

‎README.md‎

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -84,6 +84,33 @@ validation layer is enabled. Following variables need to be set to enable API lo
8484
By default logs will be written to the log file, as described above. To print the logs
8585
to stderr instead, `ZEL_LOADER_LOG_CONSOLE=1` needs to be set.
8686

87+
The API logging output format includes both function entry and exit information, showing parameter names on entry and parameter values with the result code on exit. Each log entry is timestamped and includes the logger name and log level. Example output:
88+
89+
```
90+
[2026-01-14 09:01:38.951] [ze_loader] [trace] zeContextCreate(hDriver, desc, phContext)
91+
[2026-01-14 09:01:38.951] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeContextCreate(hDriver=0x5b261fa70588, desc={stype=0x7ffdd20fe1e0, flags=0}, phContext=0x7ffdd20fe148)
92+
[2026-01-14 09:01:38.951] [ze_loader] [trace] zeCommandListCreateImmediate(hContext, hDevice, altdesc, phCommandList)
93+
[2026-01-14 09:01:38.951] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeCommandListCreateImmediate(hContext=0x5b261fa74228, hDevice=0x5b261fa708b8, altdesc={stype=0x7ffdd20fe240, ordinal=0, index=0, flags=0, mode=0x7ffdd20fe25c, priority=0x7ffdd20fe260}, phCommandList=0x7ffdd20fe150)
94+
[2026-01-14 09:01:38.951] [ze_loader] [trace] zeEventPoolCreate(hContext, desc, numDevices, phDevicesLocal, phEventPool)
95+
[2026-01-14 09:01:38.951] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeEventPoolCreate(hContext=0x5b261fa74228, desc={stype=0x7ffdd20fe200, flags=1, count=1}, numDevices=1, phDevices=0x7ffdd20fe138, phEventPool=0x7ffdd20fe160)
96+
[2026-01-14 09:01:38.951] [ze_loader] [trace] zeEventCreate(hEventPool, desc, phEvent)
97+
[2026-01-14 09:01:38.951] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeEventCreate(hEventPool=0x5b261fa19c18, desc={stype=0x7ffdd20fe220, index=0, signal=4, wait=4}, phEvent=0x7ffdd20fe158)
98+
[2026-01-14 09:01:38.951] [ze_loader] [trace] zeCommandListAppendSignalEvent(hCommandList, hEvent)
99+
[2026-01-14 09:01:38.952] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeCommandListAppendSignalEvent(hCommandList=0x5b261fa743c8, hEvent=0x5b261c69e5d8)
100+
[2026-01-14 09:01:38.952] [ze_loader] [trace] zeEventHostSynchronize(hEvent, timeout)
101+
[2026-01-14 09:01:38.954] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeEventHostSynchronize(hEvent=0x5b261c69e5d8, timeout=18446744073709551615)
102+
[2026-01-14 09:01:38.954] [ze_loader] [trace] zeContextDestroy(hContext)
103+
[2026-01-14 09:01:38.954] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeContextDestroy(hContext=0x5b261fa74228)
104+
[2026-01-14 09:01:38.954] [ze_loader] [trace] zeCommandListDestroy(hCommandList)
105+
[2026-01-14 09:01:38.955] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeCommandListDestroy(hCommandList=0x5b261fa743c8)
106+
[2026-01-14 09:01:38.955] [ze_loader] [trace] zeEventDestroy(hEvent)
107+
[2026-01-14 09:01:38.955] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeEventDestroy(hEvent=0x5b261c69e5d8)
108+
[2026-01-14 09:01:38.955] [ze_loader] [trace] zeEventPoolDestroy(hEventPool)
109+
[2026-01-14 09:01:38.955] [ze_loader] [trace] SUCCESS (ZE_RESULT_SUCCESS) in zeEventPoolDestroy(hEventPool=0x5b261fa19c18)
110+
```
111+
112+
113+
87114
# Driver/Device Sorting
88115

89116
As of v1.20.3 of the Loader, Drivers and Devices reported to the user are sorted to enable the first device to be the best available device.

‎scripts/generate_code.py‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -182,6 +182,7 @@ def _mako_loader_cpp(path, namespace, tags, version, specs, meta):
182182
'handle_lifetime.h.mako' : ('handle_lifetime_tracking', 'handle_lifetime.h'),
183183
'handle_lifetime.cpp.mako' : ('handle_lifetime_tracking', 'handle_lifetime.cpp'),
184184
'certification.h.mako' : ('checkers/certification/generated', 'certification.h'),
185+
'to_string.h.mako' : ('../../utils', 'to_string.h'),
185186
}
186187

187188
def _mako_validation_layer_cpp(path, namespace, tags, version, specs, meta):

‎scripts/templates/validation/to_string.h.mako‎

Lines changed: 171 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,171 @@
1+
<%!
2+
import re
3+
from templates import helper as th
4+
%><%
5+
n=namespace
6+
N=n.upper()
7+
8+
x=tags['$x']
9+
X=x.upper()
10+
%>/*
11+
* ***THIS FILE IS GENERATED. ***
12+
* See to_string.h.mako for modifications
13+
*
14+
* Copyright (C) 2025 Intel Corporation
15+
*
16+
* SPDX-License-Identifier: MIT
17+
*
18+
* @file ${name}
19+
*
20+
* to_string functions for Level Zero types
21+
*/
22+
23+
#ifndef _${N}_TO_STRING_H
24+
#define _${N}_TO_STRING_H
25+
26+
#include "${x}_api.h"
27+
#include <string>
28+
#include <sstream>
29+
#include <iomanip>
30+
31+
%if n == 'ze':
32+
namespace loader {
33+
34+
// Forward declarations
35+
std::string to_string(const ${x}_result_t result);
36+
37+
// Pointer to_string
38+
template<typename T>
39+
inline std::string to_string(const T* ptr) {
40+
if (ptr == nullptr) {
41+
return "nullptr";
42+
}
43+
std::ostringstream oss;
44+
oss << "0x" << std::hex << reinterpret_cast<uintptr_t>(ptr);
45+
return oss.str();
46+
}
47+
48+
%else:
49+
// Include ze_to_string.h for common definitions
50+
#include "ze_to_string.h"
51+
52+
namespace loader {
53+
%endif
54+
%if n == 'ze':
55+
// Handle to_string functions
56+
%for obj in th.extract_objs(specs, r"handle"):
57+
inline std::string to_string(${th.make_type_name(n, tags, obj)} handle) {
58+
return to_string(reinterpret_cast<const void*>(handle));
59+
}
60+
61+
%endfor
62+
%endif
63+
%if n == 'ze':
64+
// For primitive types and Level Zero typedef'd types
65+
// Since most Level Zero types are typedef'd to uint32_t, we can't distinguish them by type
66+
inline std::string to_string(uint32_t value) { return std::to_string(value); }
67+
inline std::string to_string(uint64_t value) { return std::to_string(value); }
68+
inline std::string to_string(uint8_t value) { return std::to_string(static_cast<unsigned>(value)); }
69+
inline std::string to_string(uint16_t value) { return std::to_string(value); }
70+
inline std::string to_string(int32_t value) { return std::to_string(value); }
71+
inline std::string to_string(int64_t value) { return std::to_string(value); }
72+
#if SIZE_MAX != UINT64_MAX
73+
inline std::string to_string(size_t value) { return std::to_string(value); }
74+
#endif
75+
inline std::string to_string(double value) { return std::to_string(value); }
76+
inline std::string to_string(const char* str) {
77+
if (!str) return "nullptr";
78+
return std::string("\"") + str + "\"";
79+
}
80+
81+
// Pointer to primitive types - dereference and print value
82+
inline std::string to_string(const uint32_t* ptr) {
83+
if (!ptr) return "nullptr";
84+
return to_string(*ptr);
85+
}
86+
inline std::string to_string(const uint64_t* ptr) {
87+
if (!ptr) return "nullptr";
88+
return to_string(*ptr);
89+
}
90+
inline std::string to_string(const uint8_t* ptr) {
91+
if (!ptr) return "nullptr";
92+
return to_string(*ptr);
93+
}
94+
inline std::string to_string(const uint16_t* ptr) {
95+
if (!ptr) return "nullptr";
96+
return to_string(*ptr);
97+
}
98+
inline std::string to_string(const int32_t* ptr) {
99+
if (!ptr) return "nullptr";
100+
return to_string(*ptr);
101+
}
102+
inline std::string to_string(const int64_t* ptr) {
103+
if (!ptr) return "nullptr";
104+
return to_string(*ptr);
105+
}
106+
#if SIZE_MAX != UINT64_MAX
107+
inline std::string to_string(const size_t* ptr) {
108+
if (!ptr) return "nullptr";
109+
return to_string(*ptr);
110+
}
111+
#endif
112+
inline std::string to_string(const double* ptr) {
113+
if (!ptr) return "nullptr";
114+
return to_string(*ptr);
115+
}
116+
117+
%endif
118+
// Struct to_string functions
119+
%for obj in th.extract_objs(specs, r"struct"):
120+
<%
121+
struct_name = th.make_type_name(n, tags, obj)
122+
%>\
123+
inline std::string to_string(const ${struct_name}* desc) {
124+
if (!desc) return "nullptr";
125+
std::ostringstream oss;
126+
oss << "{";
127+
%for idx, member in enumerate(obj['members']):
128+
%if member['name'] != 'pNext':
129+
<%
130+
# Extract the actual member name without array brackets
131+
member_name_full = member['name']
132+
member_name = member_name_full.split('[')[0] if '[' in member_name_full else member_name_full
133+
is_array = '[' in member_name_full
134+
135+
# Check if member is a pointer or regular value
136+
member_type = member.get('type', '')
137+
if is_array:
138+
# For arrays, just pass the array name (decays to pointer)
139+
member_access = f"desc->{member_name}"
140+
elif '*' in member_type:
141+
# It's already a pointer - pass directly
142+
member_access = f"desc->{member_name}"
143+
else:
144+
# Check if it's a struct type by looking at the type name
145+
# If it contains a struct typename pattern, take its address
146+
if '_t' in member_type and 'uint' not in member_type and 'int' not in member_type and 'size_t' not in member_type:
147+
member_access = f"&desc->{member_name}"
148+
else:
149+
member_access = f"desc->{member_name}"
150+
%>\
151+
%if idx == 0 and member['name'] == 'stype':
152+
oss << "stype=" << to_string(${member_access});
153+
%elif idx == 0:
154+
oss << "${member_name}=" << to_string(${member_access});
155+
%else:
156+
oss << ", ${member_name}=" << to_string(${member_access});
157+
%endif
158+
%endif
159+
%endfor
160+
oss << "}";
161+
return oss.str();
162+
}
163+
164+
inline std::string to_string(const ${struct_name}& desc) {
165+
return to_string(&desc);
166+
}
167+
168+
%endfor
169+
} // namespace loader
170+
171+
#endif // _${N}_TO_STRING_H

‎scripts/templates/validation/valddi.cpp.mako‎

Lines changed: 81 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,18 @@ from templates import helper as th
1919
*
2020
*/
2121
#include "${x}_validation_layer.h"
22+
#include <sstream>
23+
24+
// Define a macro for marking potentially unused functions
25+
#if defined(_MSC_VER)
26+
// MSVC doesn't support __attribute__((unused)), just omit the marking
27+
#define VALIDATION_MAYBE_UNUSED
28+
#elif defined(__GNUC__) || defined(__clang__)
29+
// GCC and Clang support __attribute__((unused))
30+
#define VALIDATION_MAYBE_UNUSED __attribute__((unused))
31+
#else
32+
#define VALIDATION_MAYBE_UNUSED
33+
#endif
2234

2335
namespace validation_layer
2436
{
@@ -33,12 +45,68 @@ namespace validation_layer
3345
);
3446

3547
%endif
36-
static ze_result_t logAndPropagateResult(const char* fname, ze_result_t result) {
37-
if (result != ${X}_RESULT_SUCCESS) {
38-
context.logger->log_trace("Error (" + loader::to_string(result) + ") in " + std::string(fname));
39-
}
48+
// Generate specific logAndPropagateResult functions for each API function
49+
%for obj in th.extract_objs(specs, r"function"):
50+
<%
51+
func_name = th.make_func_name(n, tags, obj)
52+
param_lines = [line for line in th.make_param_lines(n, tags, obj, format=['name','delim'])]
53+
param_names = [line for line in th.make_param_lines(n, tags, obj, format=['name'])]
54+
is_void_params = len(param_lines) == 0
55+
%>\
56+
%if 'condition' in obj:
57+
#if ${th.subt(n, tags, obj['condition'])}
58+
%endif
59+
VALIDATION_MAYBE_UNUSED static ze_result_t logAndPropagateResult_${func_name}(
60+
ze_result_t result\
61+
%if not is_void_params:
62+
,
63+
%for line in th.make_param_lines(n, tags, obj):
64+
${line}
65+
%endfor
66+
%endif
67+
) {
68+
std::string status = (result == ${X}_RESULT_SUCCESS) ? "SUCCESS" : "ERROR";
69+
%if is_void_params:
70+
context.logger->log_trace(status + " (" + loader::to_string(result) + ") in ${func_name}()");
71+
%else:
72+
std::ostringstream oss;
73+
oss << status << " (" << loader::to_string(result) << ") in ${func_name}(";
74+
%for i, param in enumerate([p for p in th.make_param_lines(n, tags, obj, format=['name'])]):
75+
%if i > 0:
76+
oss << ", ";
77+
%endif
78+
oss << "${param}=" << loader::to_string(${param});
79+
%endfor
80+
oss << ")";
81+
context.logger->log_trace(oss.str());
82+
%endif
83+
return result;
84+
}
85+
%if 'condition' in obj:
86+
#endif // ${th.subt(n, tags, obj['condition'])}
87+
%endif
88+
%endfor
89+
\
90+
%if n == 'ze':
91+
// Special function for zexCounterBasedEventCreate2
92+
VALIDATION_MAYBE_UNUSED static ze_result_t logAndPropagateResult_zexCounterBasedEventCreate2(
93+
ze_result_t result,
94+
ze_context_handle_t hContext,
95+
ze_device_handle_t hDevice,
96+
const void* desc,
97+
ze_event_handle_t* phEvent
98+
) {
99+
std::string status = (result == ${X}_RESULT_SUCCESS) ? "SUCCESS" : "ERROR";
100+
std::ostringstream oss;
101+
oss << status << " (" << loader::to_string(result) << ") in zexCounterBasedEventCreate2("
102+
<< "hContext=" << static_cast<const void*>(hContext) << ", "
103+
<< "hDevice=" << static_cast<const void*>(hDevice) << ", "
104+
<< "desc=" << desc << ", "
105+
<< "phEvent=" << static_cast<const void*>(phEvent) << ")";
106+
context.logger->log_trace(oss.str());
40107
return result;
41108
}
109+
%endif
42110

43111
%for obj in th.extract_objs(specs, r"function"):
44112
<%
@@ -66,7 +134,7 @@ namespace validation_layer
66134

67135
if( nullptr == ${th.make_pfn_name(n, tags, obj)} )
68136
%if ret_type == "ze_result_t":
69-
return logAndPropagateResult("${th.make_func_name(n, tags, obj)}", ${X}_RESULT_ERROR_UNSUPPORTED_FEATURE);
137+
return logAndPropagateResult_${th.make_func_name(n, tags, obj)}(${X}_RESULT_ERROR_UNSUPPORTED_FEATURE${', ' if not is_void_params else ''}${', '.join(th.make_param_lines(n, tags, obj, format=["name"]))});
70138
%else:
71139
return ${failure_return};
72140
%endif
@@ -80,7 +148,7 @@ ${line} \
80148
);
81149
if(result!=${X}_RESULT_SUCCESS) \
82150
%if ret_type == "ze_result_t":
83-
return logAndPropagateResult("${th.make_func_name(n, tags, obj)}", result);
151+
return logAndPropagateResult_${th.make_func_name(n, tags, obj)}(result${', ' if not is_void_params else ''}${', '.join(th.make_param_lines(n, tags, obj, format=["name"]))});
84152
%else:
85153
return ${failure_return};
86154
%endif
@@ -103,7 +171,7 @@ ${line} \
103171
);
104172
if(result!=${X}_RESULT_SUCCESS) \
105173
%if ret_type == "ze_result_t":
106-
return logAndPropagateResult("${th.make_func_name(n, tags, obj)}", result);
174+
return logAndPropagateResult_${th.make_func_name(n, tags, obj)}(result${', ' if not is_void_params else ''}${', '.join(th.make_param_lines(n, tags, obj, format=["name"]))});
107175
%else:
108176
return ${failure_return};
109177
%endif
@@ -134,7 +202,7 @@ driver_result );
134202
%endif
135203
if(result!=${X}_RESULT_SUCCESS) \
136204
%if ret_type == "ze_result_t":
137-
return logAndPropagateResult("${th.make_func_name(n, tags, obj)}", result);
205+
return logAndPropagateResult_${th.make_func_name(n, tags, obj)}(result${', ' if not is_void_params else ''}${', '.join(th.make_param_lines(n, tags, obj, format=["name"]))});
138206
%else:
139207
return ${failure_return};
140208
%endif
@@ -173,7 +241,7 @@ return ${failure_return};
173241
}
174242
%endif
175243
%if ret_type == "ze_result_t":
176-
return logAndPropagateResult("${th.make_func_name(n, tags, obj)}", driver_result);
244+
return logAndPropagateResult_${th.make_func_name(n, tags, obj)}(driver_result${', ' if not is_void_params else ''}${', '.join(th.make_param_lines(n, tags, obj, format=["name"]))});
177245
%else:
178246
return driver_result;
179247
%endif
@@ -203,7 +271,7 @@ return ${failure_return};
203271
auto numValHandlers = context.validationHandlers.size();
204272
for (size_t i = 0; i < numValHandlers; i++) {
205273
auto result = context.validationHandlers[i]->zeValidation->zexCounterBasedEventCreate2Prologue( hContext, hDevice, desc, phEvent );
206-
if(result!=ZE_RESULT_SUCCESS) return logAndPropagateResult("zexCounterBasedEventCreate2", result);
274+
if(result!=ZE_RESULT_SUCCESS) return logAndPropagateResult_zexCounterBasedEventCreate2(result, hContext, hDevice, desc, phEvent);
207275
}
208276

209277
if(context.enableThreadingValidation){
@@ -212,7 +280,7 @@ return ${failure_return};
212280

213281
if(context.enableHandleLifetime){
214282
auto result = context.handleLifetime->zeHandleLifetime.zexCounterBasedEventCreate2Prologue( hContext, hDevice, desc, phEvent );
215-
if(result!=ZE_RESULT_SUCCESS) return logAndPropagateResult("zexCounterBasedEventCreate2", result);
283+
if(result!=ZE_RESULT_SUCCESS) return logAndPropagateResult_zexCounterBasedEventCreate2(result, hContext, hDevice, desc, phEvent);
216284
}
217285

218286
// This is an experimental function that must be accessed through the extension mechanism
@@ -254,7 +322,7 @@ return ${failure_return};
254322

255323
for (size_t i = 0; i < numValHandlers; i++) {
256324
auto result = context.validationHandlers[i]->zeValidation->zexCounterBasedEventCreate2Epilogue( hContext, hDevice, desc, phEvent, driver_result);
257-
if(result!=ZE_RESULT_SUCCESS) return logAndPropagateResult("zexCounterBasedEventCreate2", result);
325+
if(result!=ZE_RESULT_SUCCESS) return logAndPropagateResult_zexCounterBasedEventCreate2(result, hContext, hDevice, desc, phEvent);
258326
}
259327

260328
if(driver_result == ZE_RESULT_SUCCESS && context.enableHandleLifetime){
@@ -263,7 +331,7 @@ return ${failure_return};
263331
// Note: counter-based events may not have a traditional event pool dependency
264332
}
265333
}
266-
return logAndPropagateResult("zexCounterBasedEventCreate2", driver_result);
334+
return logAndPropagateResult_zexCounterBasedEventCreate2(driver_result, hContext, hDevice, desc, phEvent);
267335
}
268336
%endif
269337
} // namespace validation_layer

0 commit comments

Comments
 (0)