Emitting trace events in Snowflake Scripting¶

You can use the Snowflake SYSTEM functions to emit trace events from a function or procedure handler written in Snowflake Scripting.

Before emitting trace events, be sure you have the trace level set so that the data you want are stored in the event table. For more information, see Setting levels for logging, metrics, and tracing.

Note

Before you can begin emitting trace events, you must set up an event table. For more information, see Event table overview.

You can access stored trace event data by executing a SELECT command on the event table. For more information, see Viewing trace data.

For general information about setting up logging and retrieving messages in Snowflake, see Trace events for functions and procedures.

Note

For guidelines to keep in mind when adding trace events, see General guidelines for adding trace events.

Adding trace events¶

You can add trace events by calling the SYSTEM$ADD_EVENT function, passing a name for the event. You can also optionally associate attributes (key-value pairs) with an event.

Code in the following example adds two events, SProcEmptyEvent and SProcEventWithAttributes. With SProcEventWithAttributes, the code also adds two attributes: key1 and key2.

SYSTEM$ADD_EVENT('SProcEmptyEvent');
SYSTEM$ADD_EVENT('SProcEventWithAttributes', {'key1': 'value1', 'key2': 'value2'});

Copy

Adding these events results in two rows in the event table, each with a different value in the RECORD column:

{
  "name": "SProcEmptyEvent"
}

Copy

{
  "name": "SProcEventWithAttributes"
}

Copy

The SProcEventWithAttributes event row includes the following attributes in the row’s RECORD_ATTRIBUTES column:

{
  "key1": "value1",
  "key2": "value2"
}

Copy

Adding span attributes¶

You can set attributes (key-value pairs) associated with spans by calling the SYSTEM$SET_SPAN_ATTRIBUTES function.

For details on spans, see How Snowflake represents trace events.

The SYSTEM$SET_SPAN_ATTRIBUTES function is available in the following form:

SYSTEM$SET_SPAN_ATTRIBUTES(<object>);

Copy

where

object is a Snowflake Scripting object with key-value pairs that specify the attributes for this trace event.

Code in the following example creates two attributes and sets their values:

SYSTEM$SET_SPAN_ATTRIBUTES('{'attr1':'value1', 'attr2':true}');

Copy

Setting these attributes results in the following in the event table’s RECORD_ATTRIBUTES column:

{
  "attr1": "value1",
  "attr2": "value2"
}

Copy

Examples¶

Code in the following example uses the SYSTEM$ADD_EVENT function to add an event named name_a and an event named name_b. With name_b, it associates two attributes, score and pass. The code also uses SYSTEM$SET_SPAN_ATTRIBUTES to set two attributes for the span, key1 and key2.

CREATE OR REPLACE PROCEDURE pi_proc()
  RETURNS DOUBLE
  LANGUAGE SQL
  AS $$
  BEGIN
    -- Add an event without attributes
    SYSTEM$ADD_EVENT('name_a');

    -- Add an event with attributes
    LET attr := {'score': 89, 'pass': TRUE};
    SYSTEM$ADD_EVENT('name_b', attr);

    -- Set attributes for the span
    SYSTEM$SET_SPAN_ATTRIBUTES({'key1': 'value1', 'key2': TRUE});

    RETURN 3.14;
  END;
  $$;

Copy

CALL pi_proc();

Copy

Automatically emit trace events for child jobs and exceptions¶

You can automatically emit the following additional types of trace events for a Snowflake Scripting stored procedure in the event table:

Exception catching.
Information about child job execution.
Child job statistics.
Stored procedure statistics, including execution time and input values.

Automatic trace emission is intended for the following use cases:

You want to emit predefined trace events without modifying the body of the stored procedure.
You want to collect information about stored procedure execution that you can analyze later, including:
- Information about child job execution (such as childJobUUID, rowCount, exceptionCode, and so on).
- Child job execution time.
- Input argument values.
You want more visibility into stored procedure execution to make it easier to develop and debug it without manually adding tracing code in the procedure.

To automatically emit these additional trace events for a stored procedure, set the AUTO_EVENT_LOGGING parameter to TRACING or ALL using the ALTER PROCEDURE command. When you set this parameter to ALL, additional log messages are also generated automatically for the stored procedure.

Important

The additional information is added to the event table only if the effective TRACE_LEVEL is set to ALWAYS or ON_EVENT. For more information, see Setting levels for logging, metrics, and tracing.

For example, create a simple table and insert data:

CREATE OR REPLACE TABLE test_auto_event_logging (id INTEGER, num NUMBER(12, 2));

INSERT INTO test_auto_event_logging (id, num) VALUES
  (1, 11.11),
  (2, 22.22);

Copy

Next, create a stored procedure named auto_event_logging_sp. This sample stored procedure updates a table row and then queries the table:

CREATE OR REPLACE PROCEDURE auto_event_logging_sp(
  table_name VARCHAR,
  id_val INTEGER,
  num_val NUMBER(12, 2))
RETURNS TABLE()
LANGUAGE SQL
AS
$$
BEGIN
  UPDATE IDENTIFIER(:table_name)
    SET num = :num_val
    WHERE id = :id_val;
  LET res RESULTSET := (SELECT * FROM IDENTIFIER(:table_name) ORDER BY id);
  RETURN TABLE(res);
EXCEPTION
  WHEN statement_error THEN
    res := (SELECT :sqlcode sql_code, :sqlerrm error_message, :sqlstate sql_state);
    RETURN TABLE(res);
END;
$$
;

Copy

The following examples set the AUTO_EVENT_LOGGING parameter for the stored procedure:

ALTER PROCEDURE auto_event_logging_sp(VARCHAR, INTEGER, NUMBER)
  SET AUTO_EVENT_LOGGING = 'TRACING';

Copy

ALTER PROCEDURE auto_event_logging_sp(VARCHAR, INTEGER, NUMBER)
  SET AUTO_EVENT_LOGGING = 'ALL';

Copy

Call the stored procedure:

CALL auto_event_logging_sp('test_auto_event_logging', 2, 44.44);

Copy

+----+-------+
| ID |   NUM |
|----+-------|
|  1 | 11.11 |
|  2 | 44.44 |
+----+-------+

Query the event table for trace data recorded by the stored procedure named auto_event_logging_sp. For each trace event, print out the timestamp, name, and attributes of the event.

SELECT
    TIMESTAMP as time,
    RECORD['name'] as event_name,
    RECORD_ATTRIBUTES as attributes,
  FROM
    my_db.public.my_events
  WHERE
    RESOURCE_ATTRIBUTES['snow.executable.name'] LIKE '%AUTO_EVENT_LOGGING_SP%'
    AND RECORD_TYPE LIKE 'SPAN%';

Copy

+-------------------------+--------------------------+-----------------------------------------------------------------------------------------------+
| TIME                    | EVENT_NAME               | ATTRIBUTES                                                                                    |
|-------------------------+--------------------------+-----------------------------------------------------------------------------------------------|
| 2024-10-25 20:48:49.844 | "snow.auto_instrumented" | {                                                                                             |
|                         |                          |   "childJobTime": 474,                                                                        |
|                         |                          |   "executionTime": 2,                                                                         |
|                         |                          |   "inputArgumentValues": "{ ID_VAL: 2, TABLE_NAME: test_auto_event_logging, NUM_VAL: 44.44 }" |
|                         |                          | }                                                                                             |
| 2024-10-25 20:48:49.740 | "child_job"              | {                                                                                             |
|                         |                          |   "childJobUUID": "01b7ef00-0003-01d1-0000-a99501233092",                                     |
|                         |                          |   "rowCount": 1,                                                                              |
|                         |                          |   "rowsAffected": 1                                                                           |
|                         |                          | }                                                                                             |
| 2024-10-25 20:48:49.843 | "child_job"              | {                                                                                             |
|                         |                          |   "childJobUUID": "01b7ef00-0003-01d1-0000-a99501233096",                                     |
|                         |                          |   "rowCount": 2,                                                                              |
|                         |                          |   "rowsAffected": 0                                                                           |
|                         |                          | }                                                                                             |
+-------------------------+--------------------------+-----------------------------------------------------------------------------------------------+

Now, call the stored procedure, but specify a table that doesn’t exist to cause an exception:

CALL auto_event_logging_sp('no_table', 2, 82.44);

Copy

+----------+-----------------------------------------------------+-----------+
| SQL_CODE | ERROR_MESSAGE                                       | SQL_STATE |
|----------+-----------------------------------------------------+-----------|
|     2003 | SQL compilation error:                              | 42S02     |
|          | Object 'NO_TABLE' does not exist or not authorized. |           |
+----------+-----------------------------------------------------+-----------+

Run the query on the event table again to see the information about the exception:

SELECT
    TIMESTAMP as time,
    RECORD['name'] as event_name,
    RECORD_ATTRIBUTES as attributes,
  FROM
    my_db.public.my_events
  WHERE
    RESOURCE_ATTRIBUTES['snow.executable.name'] LIKE '%AUTO_EVENT_LOGGING_SP%'
    AND RECORD_TYPE LIKE 'SPAN%';

Copy

+-------------------------+--------------------------+-----------------------------------------------------------------------------------------------------+
| TIME                    | EVENT_NAME               | ATTRIBUTES                                                                                          |
|-------------------------+--------------------------+-----------------------------------------------------------------------------------------------------|
| 2024-10-25 20:52:43.633 | "snow.auto_instrumented" | {                                                                                                   |
|                         |                          |   "childJobTime": 66,                                                                               |
|                         |                          |   "executionTime": 4,                                                                               |
|                         |                          |   "inputArgumentValues": "{ ID_VAL: 2, TABLE_NAME: no_table, NUM_VAL: 82.44 }"                      |
|                         |                          | }                                                                                                   |
| 2024-10-25 20:52:43.601 | "caught_exception"       | {                                                                                                   |
|                         |                          |   "exceptionCode": 2003,                                                                            |
|                         |                          |   "exceptionMessage": "SQL compilation error:\nObject 'NO_TABLE' does not exist or not authorized." |
|                         |                          | }                                                                                                   |
+-------------------------+--------------------------+-----------------------------------------------------------------------------------------------------+