diff --git a/docs/src/ref_collector.rst b/docs/src/ref_collector.rst index b469771..ddcd85e 100644 --- a/docs/src/ref_collector.rst +++ b/docs/src/ref_collector.rst @@ -106,20 +106,20 @@ functions with different log levels that take `printf` format for logging: LOG_FUNC_CALL_FATAL(const char *msg_format, ...); -Experimental: JSON trace generation ------------------------------------- +JSON format trace generation +---------------------------- As an alternative to the default text log, the collector can produce a trace in -JSON format (Perfetto). This mode is experimental and is disabled by default. +JSON format (Perfetto). This mode is disabled by default. -To enable it, set the ``EXP_LIBITTNOTIFY_GEN_JSON`` environment variable to ``1``: +To enable it, set the ``INTEL_LIBITTNOTIFY_GEN_JSON`` environment variable to ``1``: **On Linux** .. code-block:: bash - export EXP_LIBITTNOTIFY_GEN_JSON=1 + export INTEL_LIBITTNOTIFY_GEN_JSON=1 **On Windows** @@ -127,9 +127,10 @@ To enable it, set the ``EXP_LIBITTNOTIFY_GEN_JSON`` environment variable to ``1` .. code-block:: bat - set EXP_LIBITTNOTIFY_GEN_JSON=1 + set INTEL_LIBITTNOTIFY_GEN_JSON=1 -When enabled, the collector writes a ``libittnotify_refcol_.json`` file -into the log directory. The file can be opened directly in https://ui.perfetto.dev. +When enabled, the collector writes a ``libittnotify_refcol_.json`` +file into the log directory. The file can be opened directly in the +`Perfetto UI `__. diff --git a/src/ittnotify/ittnotify_config.h b/src/ittnotify/ittnotify_config.h index 875f509..deab689 100644 --- a/src/ittnotify/ittnotify_config.h +++ b/src/ittnotify/ittnotify_config.h @@ -201,7 +201,7 @@ #define API_VERSION_BUILD 20260603 #ifndef API_VERSION_NUM -#define API_VERSION_NUM 3.28.0 +#define API_VERSION_NUM 3.28.2 #endif /* API_VERSION_NUM */ #define API_VERSION "ITT-API-Version " ITT_TO_STR(API_VERSION_NUM) \ diff --git a/src/ittnotify_refcol/README.md b/src/ittnotify_refcol/README.md index 339c281..491d078 100644 --- a/src/ittnotify_refcol/README.md +++ b/src/ittnotify_refcol/README.md @@ -73,25 +73,26 @@ LOG_FUNC_CALL_ERROR(const char *msg_format, ...); LOG_FUNC_CALL_FATAL(const char *msg_format, ...); ``` -## Experimental: JSON trace generation +## JSON format trace generation As an alternative to the default text log, the collector can produce a trace in JSON format (Perfetto). -This mode is experimental and is disabled by default. +This mode is disabled by default. -To enable it, set the `EXP_LIBITTNOTIFY_GEN_JSON` environment variable to `1`: +To enable it, set the `INTEL_LIBITTNOTIFY_GEN_JSON` environment variable to `1`: **On Linux** ``` -export EXP_LIBITTNOTIFY_GEN_JSON=1 +export INTEL_LIBITTNOTIFY_GEN_JSON=1 ``` **On Windows** ``` -set EXP_LIBITTNOTIFY_GEN_JSON=1 +set INTEL_LIBITTNOTIFY_GEN_JSON=1 ``` -When enabled, the collector writes a `libittnotify_refcol_.json` file -into the log directory. The file can be opened directly in . +When enabled, the collector writes a `libittnotify_refcol_.json` +file into the log directory. The file can be opened directly in the +[Perfetto UI](https://ui.perfetto.dev). diff --git a/src/ittnotify_refcol/itt_refcol_impl.c b/src/ittnotify_refcol/itt_refcol_impl.c index 348d0ce..caa44a9 100644 --- a/src/ittnotify_refcol/itt_refcol_impl.c +++ b/src/ittnotify_refcol/itt_refcol_impl.c @@ -25,7 +25,7 @@ #define LOG_BUFFER_MAX_SIZE 256 static const char* env_log_dir = "INTEL_LIBITTNOTIFY_LOG_DIR"; -static const char* env_gen_json = "EXP_LIBITTNOTIFY_GEN_JSON"; +static const char* env_gen_json = "INTEL_LIBITTNOTIFY_GEN_JSON"; static const char* log_level_str[] = {"INFO", "WARN", "ERROR", "FATAL_ERROR"}; enum { @@ -40,7 +40,8 @@ static struct ref_collector_logger { uint8_t init_state; uint8_t first_event; uint8_t gen_json; -} g_ref_collector_logger = {NULL, 0, 1, 0}; + uint8_t paused; +} g_ref_collector_logger = {NULL, 0, 1, 0, 0}; // Collector maintains its own object lists instead of relying on __itt_global*, // because traced apps may contain multiple static ITT parts, each with its own __itt_global*. @@ -334,6 +335,12 @@ static unsigned long long get_thread_id(void) #endif } +static unsigned long long get_flow_id(const __itt_id *id) +{ + if (!id->d2) return id->d1; + return id->d1 + ((id->d2 << 19) | (id->d2 >> 45)); +} + // Escape a string so it can be safely embedded inside a JSON string literal. static void json_escape(const char* src, char* dst, size_t dst_size) { @@ -373,6 +380,8 @@ static void json_write(const char* phase, const char* cat, const char* name, { if (!g_ref_collector_logger.init_state || !g_ref_collector_logger.log_fp) return; + if (g_ref_collector_logger.paused) + return; if (!g_ref_collector_global.mutex_initialized) return; @@ -604,26 +613,33 @@ static void log_api_call( // The ITT API functions are bound to static parts via fill_func_ptr_per_lib() // and trace all ITT API calls to a file for reference/debugging purposes. // -// This reference collector implementation supports two output modes: +// The reference collector implementation supports two output modes: // // - Mode 1 (default): plain-text call logger // Writes one human-readable line per instrumented ITT API call to a .log file. -// This is the original reference-collector behavior and is used by default. +// This reference collector mode provides 4 functions with different log levels +// that take printf format string for logging: +// LOG_FUNC_CALL_INFO(const char *msg_format, ...); +// LOG_FUNC_CALL_WARN(const char *msg_format, ...); +// LOG_FUNC_CALL_ERROR(const char *msg_format, ...); +// LOG_FUNC_CALL_FATAL(const char *msg_format, ...); // -// - Mode 2 (experimental): trace event writer in JSON format (Perfetto) -// (enabled by setting EXP_LIBITTNOTIFY_GEN_JSON to a non-zero value) +// - Mode 2 : trace event writer in JSON format (Perfetto) +// Enabled by setting INTEL_LIBITTNOTIFY_GEN_JSON to a non-zero value. // Every instrumented ITT API call is translated into one or more trace events // and appended to the JSON array opened in ref_collector_init(). The resulting -// file could be loaded in https://ui.perfetto.dev. +// file could be loaded in Perfetto UI. // // Event phase mapping: -// task begin / end -> "B" / "E" (synchronous, per-thread, nestable) -// region begin / end -> "b" / "e" (asynchronous, matched by id) -// frame begin / end -> "b" / "e" (asynchronous, matched by id) -// frame submit -> "X" (complete event with explicit duration) -// counter set value -> "C" (counter series) -// formatted metadata -> task args (pinned to the enclosing task_end) -// everything else -> "i" (thread-scoped instant marker) +// task(region) begin / end -> "B" / "E" (sync, per-thread, nestable) +// overlapped task -> "b" / "e" (async, global, matched by id) +// frame begin / end -> "b" / "e" (async, global, matched by id) +// frame submit -> "X" (complete event with duration) +// counter set value -> "C" (counter series) +// formatted metadata -> task args (pinned to the enclosing task end) +// flow start -> "s" (connection keyed by the task id) +// flow finish -> "f" (connection keyed by the parent id) +// everything else -> "i" (thread-scoped instant marker) // ---------------------------------------------------------------------------- #ifdef _WIN32 @@ -876,8 +892,9 @@ static REFCOL_THREAD_LOCAL char g_pending_metadata[LOG_BUFFER_MAX_SIZE * 2] = {0 static void json_pause(void) { - json_write("i", "itt", "__itt_pause", get_timestamp_us(), + json_write("i", "ittapi", "pause", get_timestamp_us(), ",\"s\":\"t\",\"args\":{\"api\":\"pause\"}"); + g_ref_collector_logger.paused = 1; } static void json_pause_scoped(__itt_collection_scope scope) @@ -885,27 +902,32 @@ static void json_pause_scoped(__itt_collection_scope scope) char extra[LOG_BUFFER_MAX_SIZE]; snprintf(extra, sizeof(extra), ",\"s\":\"t\",\"args\":{\"api\":\"pause\",\"scope\":%d}", (int)scope); - json_write("i", "itt", "__itt_pause_scoped", get_timestamp_us(), extra); + json_write("i", "ittapi", "pause_scoped", get_timestamp_us(), extra); + g_ref_collector_logger.paused = 1; } static void json_resume(void) { - json_write("i", "itt", "__itt_resume", get_timestamp_us(), + g_ref_collector_logger.paused = 0; + json_write("i", "ittapi", "resume", get_timestamp_us(), ",\"s\":\"t\",\"args\":{\"api\":\"resume\"}"); } static void json_resume_scoped(__itt_collection_scope scope) { + g_ref_collector_logger.paused = 0; char extra[LOG_BUFFER_MAX_SIZE]; snprintf(extra, sizeof(extra), ",\"s\":\"t\",\"args\":{\"api\":\"resume\",\"scope\":%d}", (int)scope); - json_write("i", "itt", "__itt_resume_scoped", get_timestamp_us(), extra); + json_write("i", "ittapi", "resume_scoped", get_timestamp_us(), extra); } static void json_detach(void) { - json_write("i", "itt", "__itt_detach", get_timestamp_us(), + json_write("i", "ittapi", "detach", get_timestamp_us(), ",\"s\":\"t\",\"args\":{\"api\":\"detach\"}"); + g_ref_collector_logger.paused = 1; + ref_collector_release(); } static void json_thread_set_name(const char* name) @@ -917,28 +939,31 @@ static void json_thread_set_name(const char* name) char extra[LOG_BUFFER_MAX_SIZE * 2]; snprintf(extra, sizeof(extra), ",\"args\":{\"name\":\"%s\"}", name_esc); - json_write("M", "__metadata", "thread_name", get_timestamp_us(), extra); + json_write("M", "ittapi", "set_thread_name", get_timestamp_us(), extra); } -static void json_frame_begin_v3(const __itt_domain *domain, __itt_id *id) +static void json_frame_begin_v3(const __itt_domain *domain, const __itt_id *id) { if (domain == NULL) return; + if (id == NULL) id = &__itt_null; - unsigned long long fid = (id != NULL) ? id->d1 : 0; char extra[LOG_BUFFER_MAX_SIZE]; snprintf(extra, sizeof(extra), - ",\"id\":\"0x%llx\",\"args\":{\"api\":\"frame\"}", fid); + ",\"id\":\"%llu,%llu,%llu\",\"args\":{\"api\":\"frame\"," + "\"id\":\"%llu,%llu,%llu\"}", + id->d1, id->d2, id->d3, id->d1, id->d2, id->d3); json_write("b", domain->nameA, domain->nameA, get_timestamp_us(), extra); } -static void json_frame_end_v3(const __itt_domain *domain, __itt_id *id) +static void json_frame_end_v3(const __itt_domain *domain, const __itt_id *id) { if (domain == NULL) return; + if (id == NULL) id = &__itt_null; - unsigned long long fid = (id != NULL) ? id->d1 : 0; char extra[LOG_BUFFER_MAX_SIZE]; snprintf(extra, sizeof(extra), - ",\"id\":\"0x%llx\",\"args\":{\"api\":\"frame\"}", fid); + ",\"id\":\"%llu,%llu,%llu\",\"args\":{\"api\":\"frame\"}", + id->d1, id->d2, id->d3); json_write("e", domain->nameA, domain->nameA, get_timestamp_us(), extra); } @@ -961,13 +986,30 @@ static void json_task_begin( { if (domain == NULL || name == NULL) return; + uint64_t ts = get_timestamp_us(); + char extra[LOG_BUFFER_MAX_SIZE]; snprintf(extra, sizeof(extra), ",\"args\":{\"api\":\"task\"," "\"taskid\":\"%llu,%llu,%llu\",\"parentid\":\"%llu,%llu,%llu\"}", taskid.d1, taskid.d2, taskid.d3, parentid.d1, parentid.d2, parentid.d3); - json_write("B", domain->nameA, name->strA, get_timestamp_us(), extra); + json_write("B", domain->nameA, name->strA, ts, extra); + + if (parentid.d1) + { + snprintf(extra, sizeof(extra), + ",\"id\":%llu,\"bp\":\"e\",\"args\":{\"api\":\"flow\"}", + get_flow_id(&parentid)); + json_write("f", domain->nameA, "", ts, extra); + } + if (taskid.d1) + { + snprintf(extra, sizeof(extra), + ",\"id\":%llu,\"args\":{\"api\":\"flow\"}", + get_flow_id(&taskid)); + json_write("s", domain->nameA, "", ts, extra); + } } static void json_task_end(const __itt_domain *domain) @@ -989,24 +1031,29 @@ static void json_task_end(const __itt_domain *domain) } } -static void json_region_begin( - const __itt_domain *domain, __itt_id id, __itt_string_handle *name) +static void json_task_begin_overlapped( + const __itt_domain *domain, __itt_id taskid, __itt_id parentid, __itt_string_handle *name) { - if (domain == NULL || name == NULL) return; + if (domain == NULL || name == NULL || taskid.d1 == 0) return; char extra[LOG_BUFFER_MAX_SIZE]; snprintf(extra, sizeof(extra), - ",\"id\":\"0x%llx\",\"args\":{\"api\":\"region\"}", id.d1); + ",\"id\":\"%llu,%llu,%llu\",\"args\":{\"api\":\"task\"," + "\"taskid\":\"%llu,%llu,%llu\",\"parentid\":\"%llu,%llu,%llu\"}", + taskid.d1, taskid.d2, taskid.d3, + taskid.d1, taskid.d2, taskid.d3, + parentid.d1, parentid.d2, parentid.d3); json_write("b", domain->nameA, name->strA, get_timestamp_us(), extra); } -static void json_region_end(const __itt_domain *domain, __itt_id id) +static void json_task_end_overlapped(const __itt_domain *domain, __itt_id taskid) { - if (domain == NULL) return; + if (domain == NULL || taskid.d1 == 0) return; char extra[LOG_BUFFER_MAX_SIZE]; snprintf(extra, sizeof(extra), - ",\"id\":\"0x%llx\",\"args\":{\"api\":\"region\"}", id.d1); + ",\"id\":\"%llu,%llu,%llu\",\"args\":{\"api\":\"task\"}", + taskid.d1, taskid.d2, taskid.d3); json_write("e", domain->nameA, "", get_timestamp_us(), extra); } @@ -1270,12 +1317,47 @@ ITT_EXTERN_C void ITTAPI __itt_task_end(const __itt_domain *domain) LOG_FUNC_CALL_INFO("domain=%s", domain->nameA); } +ITT_EXTERN_C void ITTAPI __itt_task_begin_overlapped( + const __itt_domain *domain, __itt_id taskid, __itt_id parentid, __itt_string_handle *name) +{ + if (g_ref_collector_logger.gen_json) + { + json_task_begin_overlapped(domain, taskid, parentid, name); + return; + } + if (domain == NULL || name == NULL || taskid.d1 == 0) + { + LOG_FUNC_CALL_WARN("Incorrect function call"); + return; + } + LOG_FUNC_CALL_INFO("domain=%s name=%s taskid=%llu,%llu,%llu parentid=%llu,%llu,%llu", + domain->nameA, name->strA, + taskid.d1, taskid.d2, taskid.d3, + parentid.d1, parentid.d2, parentid.d3); +} + +ITT_EXTERN_C void ITTAPI __itt_task_end_overlapped(const __itt_domain *domain, __itt_id taskid) +{ + if (g_ref_collector_logger.gen_json) + { + json_task_end_overlapped(domain, taskid); + return; + } + if (domain == NULL || taskid.d1 == 0) + { + LOG_FUNC_CALL_WARN("Incorrect function call"); + return; + } + LOG_FUNC_CALL_INFO("domain=%s taskid=%llu,%llu,%llu", + domain->nameA, taskid.d1, taskid.d2, taskid.d3); +} + ITT_EXTERN_C void ITTAPI __itt_region_begin( const __itt_domain *domain, __itt_id id, __itt_id parentid, __itt_string_handle *name) { if (g_ref_collector_logger.gen_json) { - json_region_begin(domain, id, name); + json_task_begin(domain, id, parentid, name); return; } if (domain == NULL || name == NULL) @@ -1293,7 +1375,7 @@ ITT_EXTERN_C void ITTAPI __itt_region_end(const __itt_domain *domain, __itt_id i { if (g_ref_collector_logger.gen_json) { - json_region_end(domain, id); + json_task_end(domain); return; } if (domain == NULL) diff --git a/src/ittnotify_refcol/tests/run_smoke_test.py b/src/ittnotify_refcol/tests/run_smoke_test.py index dae75df..c736714 100644 --- a/src/ittnotify_refcol/tests/run_smoke_test.py +++ b/src/ittnotify_refcol/tests/run_smoke_test.py @@ -15,35 +15,63 @@ # ITT API names expected in the plain-text log (mode 1). EXPECTED_SYMBOLS = [ + "__itt_domain_create", + "__itt_string_handle_create", "__itt_task_begin", "__itt_task_end", "__itt_metadata_add", + "__itt_formatted_metadata_add", "__itt_frame_begin_v3", "__itt_frame_end_v3", + "__itt_frame_submit_v3", "__itt_region_begin", "__itt_region_end", + "__itt_counter_set_value_v3", + "__itt_task_begin_overlapped", + "__itt_task_end_overlapped", + "__itt_histogram_submit", + "__itt_thread_set_name", + "__itt_pause", + "__itt_resume", ] # Friendly "api" values expected in the JSON trace args (mode 2). +# Note: __itt_counter_set_value_v3 emits a "C" event whose args are the series +# value directly (no "api" tag); counters are validated by check_counter. +# Note: regions are traced identically to tasks (api "task"), so there is no +# separate "region" api value. EXPECTED_JSON_APIS = [ "task", "metadata", "frame", - "region", + "histogram", + "flow", + "pause", + "resume", ] +# Chrome Trace Event phases expected in the JSON trace (mode 2). +# B/E synchronous task and region slices +# b/e asynchronous overlapped-task and frame slices +# X frame submit (complete event) +# C counter series +# s/f flow start / finish +# i instant markers (metadata, histogram, pause, resume) +# M thread name metadata +EXPECTED_JSON_PHASES = ["B", "E", "b", "e", "X", "C", "s", "f", "i", "M"] + def run_exe(exe, lib, log_dir, gen_json): """Run the smoke test executable with the collector attached. gen_json selects the collector output mode: False -> plain-text log, - True -> JSON trace (EXP_LIBITTNOTIFY_GEN_JSON=1). + True -> JSON trace (INTEL_LIBITTNOTIFY_GEN_JSON=1). """ env = os.environ.copy() env["INTEL_LIBITTNOTIFY64"] = lib env["INTEL_LIBITTNOTIFY_LOG_DIR"] = log_dir if gen_json: - env["EXP_LIBITTNOTIFY_GEN_JSON"] = "1" + env["INTEL_LIBITTNOTIFY_GEN_JSON"] = "1" result = subprocess.run([exe], env=env) if result.returncode != 0: @@ -75,9 +103,178 @@ def check_text_log(log_dir): return True +def _api_of(event): + """Return the friendly api tag from an event's args, or None.""" + args = event.get("args") + if not isinstance(args, dict): + return None + return args.get("api") + + +def _check(condition, message): + """Print an error and return False when condition is falsy.""" + if not condition: + print(f"ERROR: {message}") + return bool(condition) + + +def check_json_phases(events): + """Every expected Chrome Trace phase is present.""" + phases = {e.get("ph") for e in events} + missing = [ph for ph in EXPECTED_JSON_PHASES if ph not in phases] + return _check(not missing, f"missing JSON phases: {missing} (got {sorted(phases)})") + + +def check_json_apis(events): + """Every expected friendly api value is present in the args.""" + seen = {_api_of(e) for e in events} + missing = [api for api in EXPECTED_JSON_APIS if api not in seen] + return _check(not missing, f"missing api values: {missing}") + + +def check_slice_balance(events): + """Synchronous (B/E) and asynchronous (b/e) slices are balanced and each + end matches a begin. The smoke test is single-threaded, so a single stack + per phase family is sufficient.""" + ok = True + + sync_open = 0 + sync_min = 0 + for e in events: + if e.get("ph") == "B": + sync_open += 1 + elif e.get("ph") == "E": + sync_open -= 1 + sync_min = min(sync_min, sync_open) + ok &= _check(sync_open == 0, f"unbalanced sync slices (net {sync_open})") + ok &= _check(sync_min >= 0, "a sync 'E' appeared with no open 'B'") + + async_begin = {e.get("id") for e in events if e.get("ph") == "b"} + async_end = {e.get("id") for e in events if e.get("ph") == "e"} + n_begin = sum(1 for e in events if e.get("ph") == "b") + n_end = sum(1 for e in events if e.get("ph") == "e") + ok &= _check(n_begin == n_end, f"async b/e count mismatch ({n_begin} vs {n_end})") + orphan_ends = async_end - async_begin + ok &= _check(not orphan_ends, f"async 'e' ids with no matching 'b': {orphan_ends}") + return ok + + +def check_overlap(events): + """At least one pair of overlapped async tasks actually overlaps, i.e. a + second 'b' opens before the first 'e' closes (non-LIFO ordering).""" + depth = 0 + max_depth = 0 + for e in events: + if e.get("ph") == "b": + depth += 1 + max_depth = max(max_depth, depth) + elif e.get("ph") == "e": + depth -= 1 + return _check(max_depth >= 2, "no overlapping async tasks observed (max concurrent < 2)") + + +def check_flows(events): + """Flow events use numeric ids, and every finish ('f') matches a start + ('s'). Flows are only emitted for synchronous slices, so each flow event + must sit inside an open B/E slice (otherwise Perfetto drops it as + flow_no_enclosing_slice).""" + ok = True + starts = {e.get("id") for e in events if e.get("ph") == "s"} + finishes = [e for e in events if e.get("ph") == "f"] + + ok &= _check(len(starts) > 0, "no flow start ('s') events found") + numeric = all( + isinstance(e.get("id"), int) + for e in events + if e.get("ph") in ("s", "f") + ) + ok &= _check(numeric, "flow ids must be numeric for Perfetto to link them") + + matched = sum(1 for e in finishes if e.get("id") in starts) + ok &= _check( + matched == len(finishes), + f"flow finishes without a matching start: {len(finishes) - matched}", + ) + + sync_open = 0 + orphan_flows = 0 + for e in events: + ph = e.get("ph") + if ph == "B": + sync_open += 1 + elif ph == "E": + sync_open = max(0, sync_open - 1) + elif ph in ("s", "f") and sync_open == 0: + orphan_flows += 1 + ok &= _check( + orphan_flows == 0, + f"{orphan_flows} flow events have no enclosing sync slice", + ) + return ok + + +def check_metadata_pinned(events): + """__itt_formatted_metadata_add is folded into the enclosing task_end, so + at least one 'E' event must carry a 'metadata' arg.""" + pinned = any( + e.get("ph") == "E" and isinstance(e.get("args"), dict) and "metadata" in e["args"] + for e in events + ) + return _check(pinned, "no task_end ('E') carries pinned formatted metadata") + + +def check_counter(events): + """Counter events ('C') carry a numeric series value.""" + counters = [e for e in events if e.get("ph") == "C"] + if not _check(counters, "no counter ('C') events found"): + return False + numeric = all( + isinstance(v, (int, float)) + for e in counters + for v in (e.get("args") or {}).values() + ) + return _check(numeric, "counter values must be numeric") + + +def check_frame_submit(events): + """Frame submit maps to a complete event ('X') with a duration.""" + submits = [e for e in events if e.get("ph") == "X"] + if not _check(submits, "no frame submit ('X') events found"): + return False + have_dur = all("dur" in e for e in submits) + return _check(have_dur, "frame submit events must carry a 'dur' field") + + +def check_thread_name(events): + """Thread naming maps to a metadata event ('M') with a name arg.""" + named = any( + e.get("ph") == "M" and (e.get("args") or {}).get("name") + for e in events + ) + return _check(named, "no thread-name ('M') event with a name arg") + + +def check_pause_suppression(events): + """The task issued between pause and resume must not appear in the trace: + no event should reference the 'smoke_test_paused' handle, and pause must + precede resume.""" + ok = True + ok &= _check( + not any("smoke_test_paused" in json.dumps(e) for e in events), + "an event issued while paused leaked into the trace", + ) + apis = [_api_of(e) for e in events] + if "pause" in apis and "resume" in apis: + ok &= _check( + apis.index("pause") < apis.index("resume"), + "pause marker must precede resume marker", + ) + return ok + + def check_json_trace(log_dir): - """Scenario 2: JSON trace is a valid Chrome Trace Event array with the - expected task events and friendly api arg values.""" + """Scenario 2: the JSON trace is a valid Chrome Trace Event array and every + instrumented ITT construct is represented with the expected shape.""" traces = glob.glob(os.path.join(log_dir, "libittnotify_refcol_*.json")) if not traces: print("ERROR: no .json file found in", log_dir) @@ -97,22 +294,33 @@ def check_json_trace(log_dir): print("ERROR: JSON trace is empty or not an array") return False - phases = {e.get("ph") for e in events} - if "B" not in phases or "E" not in phases: - print(f"ERROR: expected task begin/end (B/E) phases, got: {sorted(phases)}") - return False - - seen_apis = {e.get("args", {}).get("api") for e in events} - missing = [api for api in EXPECTED_JSON_APIS if api not in seen_apis] - if missing: - for api in missing: - print(f"ERROR: api '{api}' not found in JSON trace args") + checks = [ + ("phases", check_json_phases), + ("api values", check_json_apis), + ("slice balance", check_slice_balance), + ("async overlap", check_overlap), + ("flows", check_flows), + ("pinned metadata", check_metadata_pinned), + ("counter", check_counter), + ("frame submit", check_frame_submit), + ("thread name", check_thread_name), + ("pause suppression", check_pause_suppression), + ] + + all_ok = True + for label, fn in checks: + result = fn(events) + print(f" [{'PASS' if result else 'FAIL'}] {label}") + all_ok &= result + + if not all_ok: return False print("JSON trace scenario passed.") return True + def main(): parser = argparse.ArgumentParser(description="Run reference collector smoke test") parser.add_argument("--lib", required=True, help="Path to libittnotify_refcol shared library") @@ -149,7 +357,7 @@ def main(): if not check_text_log(text_dir): return 1 - print("\n=== Scenario 2: JSON trace (EXP_LIBITTNOTIFY_GEN_JSON=1) ===") + print("\n=== Scenario 2: JSON trace (INTEL_LIBITTNOTIFY_GEN_JSON=1) ===") if not run_exe(exe, lib, json_dir, gen_json=True): return 1 if not check_json_trace(json_dir): diff --git a/src/ittnotify_refcol/tests/smoke_test.c b/src/ittnotify_refcol/tests/smoke_test.c index 8cbc8d2..674cac0 100644 --- a/src/ittnotify_refcol/tests/smoke_test.c +++ b/src/ittnotify_refcol/tests/smoke_test.c @@ -1,18 +1,22 @@ /* Copyright (C) 2026 Intel Corporation - SPDX-License-Identifier: GPL-2.0-only OR BSD-3-Clause */ #include "ittnotify.h" #include "ittnotify_types.h" -/* Scenario 1: nested tasks with metadata attached, driven by a matrix - multiply. Exercises __itt_task_begin / __itt_metadata_add / __itt_task_end. */ +/* Scenario 1: nested tasks carrying explicit ids, plain metadata and + formatted metadata, driven by a matrix multiply. Exercises + __itt_task_begin / __itt_task_end (nested, with populated task/parent ids so + the collector emits flow events), __itt_metadata_add and + __itt_formatted_metadata_add. */ static void scenario_tasks_with_metadata(__itt_domain* domain) { - __itt_string_handle* handle = __itt_string_handle_create("smoke_test_handler"); - __itt_string_handle* handle_work = __itt_string_handle_create("smoke_test_worker"); + __itt_string_handle* handle_outer = __itt_string_handle_create("smoke_test_outer"); + __itt_string_handle* handle_inner = __itt_string_handle_create("smoke_test_inner"); + __itt_string_handle* handle_meta = __itt_string_handle_create("smoke_test_metadata"); + __itt_string_handle* handle_fmt = __itt_string_handle_create("iter=%d sum=%d"); const int n = 10; int a[10][10], b[10][10], mul[10][10], i, j, k, count = 0; @@ -33,16 +37,29 @@ static void scenario_tasks_with_metadata(__itt_domain* domain) count++; if (count % 100 == 0) { - __itt_task_begin(domain, __itt_null, __itt_null, handle_work); + /* Outer task with an explicit id (no parent). */ + __itt_id outer_id = __itt_id_make(domain, (unsigned long long)count); + __itt_task_begin(domain, outer_id, __itt_null, handle_outer); + unsigned long long data[5] = { i, j, k, count, mul[i][j] }; - __itt_metadata_add(domain, __itt_null, handle, __itt_metadata_u64, 5, data); + __itt_metadata_add(domain, __itt_null, handle_meta, + __itt_metadata_u64, 5, data); + + /* Inner task whose parent is the outer task id, so the + collector emits both a flow start and a flow finish. */ + __itt_id inner_id = __itt_id_make(domain, (unsigned long long)(count + 1)); + __itt_task_begin(domain, inner_id, outer_id, handle_inner); + __itt_formatted_metadata_add(domain, handle_fmt, i, mul[i][j]); + __itt_task_end(domain); + __itt_task_end(domain); } } } -/* Scenario 2: frames enclosing regions, with a counter updated per frame. - Exercises __itt_frame_begin_v3 / __itt_frame_end_v3, __itt_region_begin / +/* Scenario 2: frames enclosing regions, with a counter updated per frame and + an explicit frame submit. Exercises __itt_frame_begin_v3 / + __itt_frame_end_v3 / __itt_frame_submit_v3, __itt_region_begin / __itt_region_end and __itt_counter_create_v3 / __itt_counter_set_value_v3. */ static void scenario_frames_regions_counter(__itt_domain* domain) { @@ -54,10 +71,10 @@ static void scenario_frames_regions_counter(__itt_domain* domain) for (f = 0; f < frames; f++) { - __itt_id frame_id = __itt_id_make(domain, f); + __itt_id frame_id = __itt_id_make(domain, (unsigned long long)f); __itt_frame_begin_v3(domain, &frame_id); - __itt_id region_id = __itt_id_make(domain, frames + f); + __itt_id region_id = __itt_id_make(domain, (unsigned long long)(frames + f)); __itt_region_begin(domain, region_id, __itt_null, handle_region); unsigned long long value = (unsigned long long)(f + 1); @@ -65,15 +82,71 @@ static void scenario_frames_regions_counter(__itt_domain* domain) __itt_region_end(domain, region_id); __itt_frame_end_v3(domain, &frame_id); + + /* Report the same frame as a complete slice with an explicit span. */ + __itt_frame_submit_v3(domain, &frame_id, + (__itt_timestamp)(f * 1000), + (__itt_timestamp)(f * 1000 + 500)); + } +} + +/* Scenario 3: overlapped (asynchronous) tasks that intentionally do not nest. + taskA begins, taskB begins, then taskA ends before taskB - a non-LIFO order + that only the overlapped API can represent. Exercises + __itt_task_begin_overlapped / __itt_task_end_overlapped. */ +static void scenario_overlapped_tasks(__itt_domain* domain) +{ + __itt_string_handle* handle_a = __itt_string_handle_create("smoke_test_overlapped_a"); + __itt_string_handle* handle_b = __itt_string_handle_create("smoke_test_overlapped_b"); + + int anchor = 0; + const int rounds = 3; + int r; + + for (r = 0; r < rounds; r++) + { + __itt_id id_a = __itt_id_make(&anchor, (unsigned long long)(2 * r + 1)); + __itt_id id_b = __itt_id_make(&anchor, (unsigned long long)(2 * r + 2)); + + __itt_task_begin_overlapped(domain, id_a, __itt_null, handle_a); + __itt_task_begin_overlapped(domain, id_b, __itt_null, handle_b); + /* End the first task before the second - the defining overlap case. */ + __itt_task_end_overlapped(domain, id_a); + __itt_task_end_overlapped(domain, id_b); } } +/* Scenario 4: collection controls and a histogram submit. Exercises + __itt_thread_set_name, __itt_histogram_create / __itt_histogram_submit and + __itt_pause / __itt_resume (the task issued while paused must be suppressed + in the JSON trace). */ +static void scenario_controls_and_histogram(__itt_domain* domain) +{ + __itt_string_handle* handle_ignored = __itt_string_handle_create("smoke_test_paused"); + + __itt_thread_set_name("smoke_test_main"); + + __itt_histogram* hist = __itt_histogram_create(domain, "smoke_test_histogram", + __itt_metadata_u64, __itt_metadata_u64); + unsigned long long x_data[4] = { 0, 1, 2, 3 }; + unsigned long long y_data[4] = { 10, 20, 30, 40 }; + __itt_histogram_submit(hist, 4, x_data, y_data); + + /* Everything between pause and resume must not appear in the JSON trace. */ + __itt_pause(); + __itt_task_begin(domain, __itt_null, __itt_null, handle_ignored); + __itt_task_end(domain); + __itt_resume(); +} + int main(void) { __itt_domain* domain = __itt_domain_create("smoke_test_domain"); scenario_tasks_with_metadata(domain); scenario_frames_regions_counter(domain); + scenario_overlapped_tasks(domain); + scenario_controls_and_histogram(domain); return 0; }