HiveBrain v1.2.0
Get Started
← Back to all entries
patternModerate

Relating ExecutionInstanceGUID to the SSISDB

Submitted by: @import:stackexchange-dba··
0
Viewed 0 times
ssisdbtheexecutioninstanceguidrelating

Problem

The 2012 release of SQL Server Integration Services, SSIS, has delivered an SSISDB catalog which tracks the operations of packages (among other things). The default package execution for solutions using the Project Deployment model will have logging to the SSISDB turned on.

When a package executes, the System::ExecutionInstanceGUID is populated with a value that, if one were using explicit logging (to sys.sysdtslog90/sys.sysssislog) would record all the events for a specific package execution.

What I'd like to know, is how do I tie an ExecutionInstanceGUID to anything in the SSISDB catalog. Alternatively, is an SSIS package executing in the SSISDB privy to the value of its catalog.executions.execution_id

Ultimately, I am trying to use the existing, custom audit table and link it back to the detailed history in the SSISDB catalog but can't seem to find the link.

Solution

I created a SSIS project using the 2012 Deployment Model consisting of a single package. In that package, I added an OLE DB Connection Manager, pointed it to tempdb and dropped a Script Task onto the canvas. I also turned on explicit logging using that OLE DB Connection Manager and captured the OnInformation event.

SCR Fire info

I configured my script task to grab two parameters: System::ExecutionInstanceGUID and System::ServerExecutionID I will admit at this point, I had not noticed the second variable until Marian's answer. Inside the task, I raise 2 Information events so I can get the values recorded. This should be logged to both the explicit table (dbo.sysssislog) and the "free" logging (catalog.operation_messages).

public void Main()
    {
        bool fireAgain = true;
        string description = string.Empty;
        string variable = string.Empty;
        string value = string.Empty;

        variable = "System::ServerExecutionID";
        value = Dts.Variables[variable].Value.ToString();
        description = string.Format("{0}: {1}", variable, value);
        Dts.Events.FireInformation(0, "Reporting", description, string.Empty, 0, ref fireAgain);

        variable = "System::ExecutionInstanceGUID";
        value = Dts.Variables[variable].Value.ToString();
        description = string.Format("{0}: {1}", variable, value);
        Dts.Events.FireInformation(0, "Reporting", description, string.Empty, 0, ref fireAgain);

        Dts.TaskResult = (int)ScriptResults.Success;
    }


Deploy and execute

I then deployed my project to a server and executed it.

I opened the Operations Report and and clicked into the SCR Fire info task details.

The red circled item shows that we are viewing details for Operation 8, as expected. The highlighted lines are the OnInformation events which bubbled up the values of those two system variables. Also as expected, the value of System::ServerExecutionID matched what was in the report. The value of System::ExecutionInstanceGUID was meaningless as always but it was present {3F515780-8062-40AA-B9EC-C320CBAC5EFD}.

Tying it all together

I now had a two different logs I wanted to tie together.

sysssislog query

Running this query pulled back relevant rows from the old-school logging table.

SELECT
    L.event
,   L.source
,   L.message 
FROM
    dbo.sysssislog AS L
WHERE
    L.executionid = '{3F515780-8062-40AA-B9EC-C320CBAC5EFD}'
ORDER BY
    L.id ASC;


The results looked like

event   source  message
PackageStart    ParameterTest   Beginning of package execution.

OnInformation   SCR Fire info   System::ServerExecutionID: 8
OnInformation   ParameterTest   System::ServerExecutionID: 8
OnInformation   SCR Fire info   System::ExecutionInstanceGUID: {3F515780-8062-40AA-B9EC-C320CBAC5EFD}
OnInformation   ParameterTest   System::ExecutionInstanceGUID: {3F515780-8062-40AA-B9EC-C320CBAC5EFD}
PackageEnd  ParameterTest   End of package execution.


catalog.operation_messages query

Running this query against the SSISDB catalog showed all the messages that were in the above report and also confirmed I could link the value in message to operation_id as well as over to dbo.sysssislog.executionid

SELECT 
    OM.* 
FROM 
    catalog.operation_messages AS OM
WHERE
    OM.operation_id = 8;


Those results were

operation_message_id    operation_id    message_time    message_type    message_source_type message extended_info_id
30  8   2013-04-02 21:02:34.1418917 -05:00  10  30  ParameterTest:Validation has started.   NULL
31  8   2013-04-02 21:02:34.1738922 -05:00  10  40  SCR Fire info:Validation has started.   NULL
32  8   2013-04-02 21:02:34.1768872 -05:00  20  40  SCR Fire info:Validation is complete.   NULL
33  8   2013-04-02 21:02:34.1788903 -05:00  20  30  ParameterTest:Validation is complete.   NULL
34  8   2013-04-02 21:02:34.3349188 -05:00  30  30  ParameterTest:Start, 9:02:34 PM.    NULL
35  8   2013-04-02 21:02:34.4009253 -05:00  30  40  SCR Fire info:Start, 9:02:34 PM.    NULL
36  8   2013-04-02 21:02:34.4009253 -05:00  10  40  SCR Fire info:Validation has started.   NULL
37  8   2013-04-02 21:02:34.4019251 -05:00  20  40  SCR Fire info:Validation is complete.   NULL
38  8   2013-04-02 21:02:34.4219283 -05:00  70  40  SCR Fire info:Information: System::ServerExecutionID: 8 NULL
39  8   2013-04-02 21:02:34.4259295 -05:00  70  40  SCR Fire info:Information: System::ExecutionInstanceGUID: {3F515780-8062-40AA-B9EC-C320CBAC5EFD}    NULL
40  8   2013-04-02 21:02:34.4409316 -05:00  40  40  SCR Fire info:Finished, 9:02:34 PM, Elapsed time: 00:00:00.031. NULL
41  8   2013-04-02 21:02:34.4419388 -05:00  40  30  ParameterTest:Finished, 9:02:34 PM, Elapsed time: 00:00:00.125. NULL


Wrap up

When the package is executed outside of the context of the SSISDB catalog (aka via SSDT-BI or the command line to an .ispac) the value of the the System::ServerExecutionID will be 0. It makes sense, but future readers either use a LEF

Code Snippets

public void Main()
    {
        bool fireAgain = true;
        string description = string.Empty;
        string variable = string.Empty;
        string value = string.Empty;

        variable = "System::ServerExecutionID";
        value = Dts.Variables[variable].Value.ToString();
        description = string.Format("{0}: {1}", variable, value);
        Dts.Events.FireInformation(0, "Reporting", description, string.Empty, 0, ref fireAgain);

        variable = "System::ExecutionInstanceGUID";
        value = Dts.Variables[variable].Value.ToString();
        description = string.Format("{0}: {1}", variable, value);
        Dts.Events.FireInformation(0, "Reporting", description, string.Empty, 0, ref fireAgain);

        Dts.TaskResult = (int)ScriptResults.Success;
    }
SELECT
    L.event
,   L.source
,   L.message 
FROM
    dbo.sysssislog AS L
WHERE
    L.executionid = '{3F515780-8062-40AA-B9EC-C320CBAC5EFD}'
ORDER BY
    L.id ASC;
event   source  message
PackageStart    ParameterTest   Beginning of package execution.

OnInformation   SCR Fire info   System::ServerExecutionID: 8
OnInformation   ParameterTest   System::ServerExecutionID: 8
OnInformation   SCR Fire info   System::ExecutionInstanceGUID: {3F515780-8062-40AA-B9EC-C320CBAC5EFD}
OnInformation   ParameterTest   System::ExecutionInstanceGUID: {3F515780-8062-40AA-B9EC-C320CBAC5EFD}
PackageEnd  ParameterTest   End of package execution.
SELECT 
    OM.* 
FROM 
    catalog.operation_messages AS OM
WHERE
    OM.operation_id = 8;
operation_message_id    operation_id    message_time    message_type    message_source_type message extended_info_id
30  8   2013-04-02 21:02:34.1418917 -05:00  10  30  ParameterTest:Validation has started.   NULL
31  8   2013-04-02 21:02:34.1738922 -05:00  10  40  SCR Fire info:Validation has started.   NULL
32  8   2013-04-02 21:02:34.1768872 -05:00  20  40  SCR Fire info:Validation is complete.   NULL
33  8   2013-04-02 21:02:34.1788903 -05:00  20  30  ParameterTest:Validation is complete.   NULL
34  8   2013-04-02 21:02:34.3349188 -05:00  30  30  ParameterTest:Start, 9:02:34 PM.    NULL
35  8   2013-04-02 21:02:34.4009253 -05:00  30  40  SCR Fire info:Start, 9:02:34 PM.    NULL
36  8   2013-04-02 21:02:34.4009253 -05:00  10  40  SCR Fire info:Validation has started.   NULL
37  8   2013-04-02 21:02:34.4019251 -05:00  20  40  SCR Fire info:Validation is complete.   NULL
38  8   2013-04-02 21:02:34.4219283 -05:00  70  40  SCR Fire info:Information: System::ServerExecutionID: 8 NULL
39  8   2013-04-02 21:02:34.4259295 -05:00  70  40  SCR Fire info:Information: System::ExecutionInstanceGUID: {3F515780-8062-40AA-B9EC-C320CBAC5EFD}    NULL
40  8   2013-04-02 21:02:34.4409316 -05:00  40  40  SCR Fire info:Finished, 9:02:34 PM, Elapsed time: 00:00:00.031. NULL
41  8   2013-04-02 21:02:34.4419388 -05:00  40  30  ParameterTest:Finished, 9:02:34 PM, Elapsed time: 00:00:00.125. NULL

Context

StackExchange Database Administrators Q#38808, answer score: 10

Revisions (0)

No revisions yet.