SSIS Junkie : sql server integration services, sql server

sp_ssiscatalog v1.0.2.0 now available for download [SSIS]

jamiet — Mon, 11 Mar 2013 22:51:20 GMT

v1.0.2.0 – what’s in it?

Things have been a bit quiet on the sp_ssiscatalog front since I last blogged about it three months ago in December 2012. Rest-assured development continues apace however and today I’m making available a minor update, v1.0.2.0 which is now available for download from Codeplex. For those that don’t know I describe sp_ssiscatalog as:

sp_ssiscatalog is a stored procedure that makes it easy to query for information that is strewn around the SSIS Catalog.

There aren’t too many functional changes in this release, it is more focused on making sp_ssiscatalog easier to use. Back in Documenting sp_ssiscatalog I explained how I was adding documentation to the messages tab of SSMS. Hence as of this new release when you execute sp_ssiscatalog you will see information such as this:

which I think should be very useful for anyone that wants to use sp_ssiscatalog to its fullest. Even I who wrote the thing and has been using it day-in, day-out for quite some time now can’t remember the names of all the parameters – now I no longer have to!

Note that you can turn off the display of the documentation using the @show_docs parameter:

exec sp_ssiscatalog @show_docs=0

If you want to display only the documentation and not actually have sp_ssiscatalog do any querying of the SSIS Catalog its @show_docs_only:

exec sp_ssiscatalog @show_docs_only=1

If you have any suggestions for future enhancements please put them in the comments below or submit them to the discussions page on the Codeplex site.

As a reminder, here is the sort of thing you can do with sp_ssiscatalog:

--Return all failed executions  
EXEC [dbo].[sp_ssiscatalog] @operation_type='execs',@execs_status_desc='failed'


--Return all executions for a specified folder
EXEC [dbo].[sp_ssiscatalog] @operation_type='execs',@execs_folder_name='My folder'


--Return all executions of a specified package in a specified project
EXEC [dbo].[sp_ssiscatalog] @operation_type='execs',@execs_project_name='My project', @execs_package_name='Pkg.dtsx'


--Return information about the most recent execution
EXEC [dbo].[sp_ssiscatalog]

One last thing, if sp_ssiscatalog is useful to you and you’d like to support future development feel free to donate to my personal beer fund at http://www.paypal.com/cgi-bin/webscr?cmd=_xclick&business=jamie@jamie-thomson.net&item_name=Supporting%20sp_ssiscatalog.

Installation Instructions

Download the zip file at DB v1.0.2.0. It contains two files, SsisReportingPack.dacpac & SSISDB.dacpac
Unzip to a folder of your choosing
Open a command prompt and change to the directory into which you unzipped the files
Execute:
- "%PROGRAMFILES(x86)%\Microsoft SQL Server\110\DAC\bin\sqlpackage.exe" /a:Publish /tdn:SsisReportingPack /sf:SSISReportingPack.dacpac /v:SSISDB=SSISDB /tsn:(local)
  (/tsn specifies the target server, change as appropriate. /tdn specifies the database name, you can call it whatever you like.)

If everything works OK you’ll see something like the following:

This will (if it doesn’t already exist) create a database called [SsisReportingPack] (or whatever you chose to call it) which contains [dbo].[sp_ssiscatalog].

The perils of double-dash comments [T-SQL]

jamiet — Thu, 06 Dec 2012 09:21:39 GMT

I was checking my Twitter feed on my way in to work this morning and was alerted to an interesting blog post by Valentino Vranken that highlights a problem regarding the OLE DB Source in SSIS. In short, using double-dash comments in SQL statements within the OLE DB Source can cause unexpected results. It really is quite an important read if you’re developing SSIS packages so head over to SSIS OLE DB Source, Parameters And Comments: A Dangerous Mix! and be educated. Note that the problem is solved in SSIS2012 and Valentino explains exactly why.

If reading Valentino’s post has switched your brain into “learn mode” perhaps also check out my post SSIS: SELECT *... or select from a dropdown in an OLE DB Source component? which highlights another issue to be aware of when using the OLE DB Source.

As I was reading Valentino’s post I was reminded of a slidedeck by Chris Adkin entitled T-SQL Coding Guidelines where he recommends never using double-dash comments:

That’s good advice!

@Jamiet

SSIS Reporting Pack – a performance tip

jamiet — Mon, 05 Nov 2012 22:36:41 GMT

SSIS Reporting Pack is a suite of open source SQL Server Reporting Services (SSRS) reports that provide additional insight into the SQL Server Integration Services (SSIS) 2012 Catalog. You can read more about SSIS Reporting Pack here on my blog or had over to the home page for the project at http://ssisreportingpack.codeplex.com/.

After having used SSRS Reporting Pack on a real project for a few months now I have come to realise that if you have any sizeable data volumes in [SSISDB] then the reports in SSIS Reporting Pack will suffer from chronic performance problems – I have seen the “execution” report take upwards of 30minutes to return data. To combat this I highly recommend that you create an index on the [SSISDB].[internal].[event_messages].[operation_id] & [SSISDB].[internal].[operation_messages].[operation_id] fields. Phil Brammer has experienced similar problems himself and has since made it easy for the rest of us by preparing some scripts to create the indexes that he recommends and he has shared those scripts via his blog at http://www.ssistalk.com/SSIS_2012_Missing_Indexes.zip. If you are using SSIS Reporting Pack, or even if you are simply querying [SSISDB], I highly recommend that you download Phil’s scripts and test them out on your own SSIS Catalog(s).

Those indexes will not solve all problems but they will make some of your reports run quicker. I am working on some further enhancements that should further improve the performance of the reports. Watch this space.

@Jamiet

Querying the SSIS Catalog? Here’s a handy query!

jamiet — Wed, 17 Oct 2012 12:05:57 GMT

I’ve been working on a SQL Server Integration Services (SSIS) solution for about 6 months now and I’ve learnt many many things that I intend to share on this blog just as soon as I get the time. Here’s a very short starter-for-ten…

I’ve found the following query to be utterly invaluable when interrogating the SSIS Catalog to discover what is going on in my executions:

SELECT event_message_id,MESSAGE,package_name,event_name,message_source_name,package_path,execution_path,message_type,message_source_type
FROM   (
       SELECT  em.*
       FROM    SSISDB.catalog.event_messages em
       WHERE   em.operation_id = (SELECT MAX(execution_id) FROM SSISDB.catalog.executions)
           AND event_name NOT LIKE '%Validate%'
       )q
/* Put in whatever WHERE predicates you might like*/
--WHERE	event_name = 'OnError'
--WHERE	package_name = 'Package.dtsx'
--WHERE execution_path LIKE '%<some executable>%'
ORDER BY message_time DESC

Know it. Learn it. Love it.

@jamiet

Should we be able to deploy a single package to the SSIS Catalog?

jamiet — Tue, 16 Oct 2012 08:18:14 GMT

My buddy Sutha Thiru sent me an email recently asking about my opinion on a particular nuance of the project deployment model in SQL Server Integration Services (SSIS) 2012 and I’d like to share my response as I think it warrants a wider discussion. Sutha asked:

Jamie

What is your take on this?
http://www.mattmasson.com/index.php/2012/07/can-i-deploy-a-single-ssis-package-from-my-project-to-the-ssis-catalog/

Overnight I was talking to Matt who confirmed that they got no plans to change the deployment model.
For example if we have following scenrio how do we do deploy?

Sprint 1
Pkg1, 2 & 3 has been developed and deployed to UAT. Once signed off its been deployed to Live.

Sprint 2
Pkg 4 & 5 been developed. During this time users raised a bug on Pkg2. We want to make the change to Pkg2 and deploy that to UAT and eventually to LIVE without releasing Pkg 4 &5.
How do we do it?

Matt pointed me to his blog entry which I have seen before . http://www.mattmasson.com/index.php/2012/02/thoughts-on-branching-strategies-for-ssis-projects/

Thanks
Sutha

My response:

Personally, even though I've experienced the exact problem you just outlined, I agree with the current approach. I steadfastly believe that there should not be a way for an unscrupulous developer to slide in a new version of a package under the covers. Deploying .ispac files brings a degree of rigour to your operational processes.

Yes, that means that we as SSIS developers are going to have to get better at using source control and branching properly but that is no bad thing in my opinion. Claiming to be proper "developers" is a bit of a cheap claim if we don't even do the fundamentals correctly.

I would be interested in the thoughts of others who have used the project deployment model. Do you agree with my point of view?

@Jamiet

SSIS Catalog, Windows updates and deployment failures due to System.Core mismatch

jamiet — Wed, 11 Jul 2012 14:36:23 GMT

This is a heads-up for anyone doing development on SSIS.

On my current project where we are implementing a SQL Server Integration Services (SSIS) 2012 solution we recently encountered a situation where we were unable to deploy any of our projects even though we had successfully deployed in the past. Any attempt to use the deployment wizard resulted in this error dialog:

The text of the error (for all you search engine crawlers out there) was:

A .NET Framework error occurred during execution of user-defined routine or aggregate "create_key_information":
System.IO.FileLoadException: Could not load file or assembly 'System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089' or one of its dependencies. The located assembly's manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040) ---> System.IO.FileLoadException: The located assembly's manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)
System.IO.FileLoadException:
System.IO.FileLoadException:
at Microsoft.SqlServer.IntegrationServices.Server.Security.CryptoGraphy.CreateSymmetricKey(String algorithm)
at Microsoft.SqlServer.IntegrationServices.Server.Security.CryptoGraphy.CreateKeyInformation(SqlString algorithmName, SqlBytes& key, SqlBytes& IV)
. (Microsoft SQL Server, Error: 6522)

After some investigation and a bit of back and forth with some very helpful members of the SSIS product team (hey Matt, Wee Hyong) it transpired that this was due to a .Net Framework fix that had been delivered via Windows Update. I took a look at the server update history and indeed there have been some recently applied .Net Framework updates:

This fix had (in the words of Matt Masson) “somehow caused a mismatch on System.Core for SQLCLR” and, as you may know, SQLCLR is used heavily within the SSIS Catalog. The fix was pretty simple – restart SQL Server. This causes the assemblies to be upgraded automatically. If you are using Data Quality Services (DQS) you may have experienced similar problems which are documented at Upgrade SQLCLR Assemblies After .NET Framework Update. I am hoping the SSIS team will follow-up with a more thorough explanation on their blog soon.

You DBAs out there may be questioning why Windows Update is set to automatically apply updates on our production servers. We’re checking that out with our hosting provider right now

You have been warned!

@Jamiet

Using Find/Replace with regular expressions inside a SSIS package

jamiet — Tue, 12 Jun 2012 08:56:37 GMT

Another one of those might-be-useful-again-one-day-so-I’ll-share-it-in-a-blog-post blog posts

I am currently working on a SQL Server Integration Services (SSIS) 2012 implementation where each package contains a parameter called ETLIfcHist_ID:

During normal execution this will get altered when the package is executed from the Execute Package Task however we want to make sure that at deployment-time they all have a default value of –1. Of course, they tend to get changed during development so I wanted a way of easily changing them all back to the default value. Opening up each package in turn and editing them was an option but given that we have over 40 packages and we might want to carry out this reset fairly frequently I needed a more automated method so I turned to Visual Studio’s Find/Replace… feature

Of course, we don’t know what value will be in that parameter so I can’t simply search for a particular value; hence I opted to use a regular expression to identify the value to be change. In the rest of this blog post I’ll explain how to do that.

For demonstration purposes I have taken the contents of a .dtsx file and stripped out everything except the element containing the parameters (<DTS:PackageParameters>), if you want to play along at home you can copy-paste the XML document below into a new XML file and open it up in Visual Studio:

<?xml version="1.0"?>
<DTS:Executable xmlns:DTS="www.microsoft.com/SqlServer/Dts">
  <DTS:PackageParameters>
    <DTS:PackageParameter
      DTS:CreationName=""
      DTS:DataType="3"
      DTS:Description="InterfaceHistory_ID: used for Lineage"
      DTS:DTSID="{635616DB-EEEE-45C8-89AA-713E25846C7E}"
      DTS:ObjectName="ETLIfcHist_ID">
      <DTS:Property
        DTS:DataType="3"
        DTS:Name="ParameterValue">VALUE_TO_BE_CHANGED</DTS:Property>
    </DTS:PackageParameter>
    <DTS:PackageParameter
      DTS:CreationName=""
      DTS:DataType="3"
      DTS:Description="Some other description"
      DTS:DTSID="{635616DB-EEEE-45C8-89AA-713E25845C7E}"
      DTS:ObjectName="SomeOtherObjectName">
      <DTS:Property
        DTS:DataType="3"
        DTS:Name="ParameterValue">SomeOtherValue</DTS:Property>
    </DTS:PackageParameter>
  </DTS:PackageParameters>
</DTS:Executable>

We are trying to identify the value of the parameter whose name is ETLIfcHist_ID – notice that in the XML document above that value is VALUE_TO_BE_CHANGED. The following regular expression will find the appropriate portion of the XML document:

{\<DTS\:PackageParameter[\n ]*DTS\:CreationName="[A-Za-z0-9\:_\{\}- ]*"[\n ]*DTS\:DataType="[A-Za-z0-9\:_\{\}- ]*"[\n ]*DTS\:Description="[A-Za-z0-9\:_\{\}- ]*"[\n ]*DTS\:DTSID="[A-Za-z0-9\:_\{\}- ]*"[\n ]*DTS\:ObjectName="ETLIfcHist_ID"\>[\n ]*\<DTS\:Property[\n ]*DTS\:DataType="[A-Za-z0-9\:_\{\}- ]*"[\n ]*DTS\:Name="ParameterValue"\>}[A-Za-z0-9\:_\{\}- ]*{\<\/DTS\:Property\>}

I have highlighted the name of the parameter that we’re looking for. I have also highlighted two portions identified by pairs of curly braces “{…}”; these are important because they pick out the two portions either side of the value I want to replace, in other words the portions highlighted here:

<DTS:PackageParameters>
    <DTS:PackageParameter
      DTS:CreationName=""
      DTS:DataType="3"
      DTS:Description="InterfaceHistory_ID: used for Lineage"
      DTS:DTSID="{635616DB-EEEE-45C8-89AA-713E25846C7E}"
      DTS:ObjectName="ETLIfcHist_ID">
      <DTS:Property
        DTS:DataType="3"
        DTS:Name="ParameterValue">VALUE_TO_BE_CHANGED</DTS:Property>
    </DTS:PackageParameter>

Those sections in the curly braces are termed tag expressions and can be identified in the replace expression using a backslash and a number identifying which tag expression you’re referring to according to its ordinal position. Hence, our replace expression is simply:

\1-1\2

We’re saying the portion of our file identified by the regular expression should be replaced by the first curly brace section, then the literal –1, then the second curly brace section. Make sense? Give it a go yourself by plugging those two expressions into Visual Studio’s Find and Replace dialog. If you set it to look in “All Open Documents” then you can open up the code-behind of all your packages and change all of them at once. The Find and Replace dialog will look like this:

That’s it! I realise that not everyone will be looking to change the value of a parameter but hopefully I have shown you a technique that you can modify to work for your own scenario.

Given that this blog post is, y’know, on the web I have no doubt that someone is going to find a fault with my find regex expression and if that person is you….that’s OK. Let me know about it in the comments below and perhaps we can work together to come up with something better! Note that some parameters may have a different set of properties (for example some, but not all, of my parameters have a DTS:Required attribute) so your find regular expression may have to change accordingly.

When researching this I found the following article to be invaluable: Visual Studio Find/Replace Regular Expression Usage

@Jamiet

Variable enhancements in RC0 [SSIS]

jamiet — Wed, 22 Feb 2012 22:56:00 GMT

I have been poking around idly in the RC0 release of SQL Server Integration Services (SSIS) 2012 and noticed a few nice enhancements that hadn’t really hit the newsstands as yet (well, I didn’t know about them anyway). Here is a quick rundown:

Expression is viewable in the Variables window

Fairly self-explanatory this one. If a variable has an expression applied to it that expression can now be seen in the Variables window; also notice that the variable icon gets an adorner specifying that there is an expression upon it. What is not so obvious is that if you add an expression to a variable then the EvaluateAsExpression property of that variable is automatically set to True:

That’s a welcome enhancement.

New System Variables

There are some new System variables available to you, some of which might be useful (one of which is very useful indeed):

I have not found any documentation on these as yet so I’ll take a guess at what are for:

IgnoreConfigurationsOnLoad – This is a boolean variable so I can only assume it does what it says on the tin – ignores configurations. The default value is False. I would assume that this doesn’t have any affect if you are using the new project deployment model.
ProductVersion and LastModifiedProductVersion – In the package I am looking at these are both set to 11.0.1750.32 which is the same build number as in Help->About

The only thing I don’t understand is that if this package was built in a prior version (CTP3) why they are set to the same value?

ServerExecutionID – This one is very useful indeed. It provides the ExecutionID that the SSIS Catalog assigned to the current execution.

Hope that helps!

@jamiet

SQL Server Configuration timeouts - and a workaround [SSIS]

jamiet — Wed, 30 Nov 2011 21:43:33 GMT

Ever since I started writing SSIS packages back in 2004 I have opted to store configurations in .dtsConfig (.i.e. XML) files rather than in a SQL Server table (aka SQL Server Configurations) however recently I inherited some packages that used SQL Server Configurations and thus had to immerse myself in their murky little world. To all the people that have ever gone onto the SSIS forum and asked questions about ambiguous behaviour of SQL Server Configurations I now say this... I feel your pain!

The biggest problem I have had was in dealing with the change to the order in which configurations get applied that came about in SSIS 2008. Those changes are detailed on MSDN at SSIS Package Configurations however the pertinent bits are:

As the utility loads and runs the package, events occur in the following order:

The dtexec utility loads the package.

The utility applies the configurations that were specified in the package at design time and in the order that is specified in the package. (The one exception to this is the Parent Package Variables configurations. The utility applies these configurations only once and later in the process.)

The utility then applies any options that you specified on the command line.

The utility then reloads the configurations that were specified in the package at design time and in the order specified in the package. (Again, the exception to this rule is the Parent Package Variables configurations). The utility uses any command-line options that were specified to reload the configurations. Therefore, different values might be reloaded from a different location.

The utility applies the Parent Package Variable configurations.

The utility runs the package.

To understand how these steps differ from SSIS 2005 I recommend reading Doug Laudenschlager’s blog post Understand how SSIS package configurations are applied.

The very nature of SQL Server Configurations means that the Connection String for the database holding the configuration values needs to be supplied from the command-line. Typically then the call to execute your package resembles this:

dtexec /FILE Package.dtsx /SET "\Package.Connections[SSISConfigurations].Properties[ConnectionString]";"\"Data Source=SomeServer;Initial Catalog=SomeDB;Integrated Security=SSPI;\"",

The problem then is that, as per the steps above, the package will (1) attempt to apply all configurations using the Connection String stored in the package for the "SSISConfigurations" Connection Manager before then (2) applying the Connection String from the command-line and then (3) apply the same configurations all over again. In the packages that I inherited that first attempt to apply the configurations would timeout (not unexpected); I had 8 SQL Server Configurations in the package and thus the package was waiting for 2 minutes until all the Configurations timed out (i.e. 15seconds per Configuration) - in a package that only executes for ~8seconds when it gets to do its actual work a delay of 2minutes was simply unacceptable.

We had three options in how to deal with this:

Get rid of the use of SQL Server configurations and use .dtsConfig files instead
Edit the packages when they get deployed
Change the timeout on the "SSISConfigurations" Connection Manager

#1 was my preferred choice but, for reasons I explain below*, wasn't an option in this particular instance. #2 was discounted out of hand because it negates the point of using Configurations in the first place. This left us with #3 - change the timeout on the Connection Manager. This is done by going into the properties of the Connection Manager, opening the "All" tab and changing the Connect Timeout property to some suitable value (in the screenshot below I chose 2 seconds).

This change meant that the attempts to apply the SQL Server configurations timed out in 16 seconds rather than two minutes; clearly this isn't an optimum solution but its certainly better than it was.

So there you have it - if you are having problems with SQL Server configuration timeouts within SSIS try changing the timeout of the Connection Manager. Better still - don't bother using SQL Server Configuration in the first place. Even better - install RC0 of SQL Server 2012 to start leveraging SSIS parameters and leave the nasty old world of configurations behind you.

@Jamiet

* Basically, we are leveraging a SSIS execution/logging framework in which the client had invested a lot of resources and SQL Server Configurations are an integral part of that.

SSIS Reporting Pack v0.2 now available

jamiet — Sun, 04 Sep 2011 13:57:00 GMT

In December 2010 I announced in a blog post Introducing SSIS Reporting Pack for SQL Server code-named Denali that I planned to provide a series of reports that visualised information held in the SSIS Catalog in SQL Server Denali – I called these reports the SSIS Reporting Pack. At that time SSIS Reporting Pack was a precursor to what I really wanted to provide because the reports were built upon the SSIS Catalog from Denali CTP1; Denali CTP3 brought with it a whole heap of changes to the SSIS Catalog (read more at SSIS Logging in Denali) and accordingly SSIS Reporting Pack has been enhanced dramatically.

Download and Install

You can always download the latest release of SSIS Reporting Pack from http://ssisreportingpack.codeplex.com/releases/. In the release that I am announcing today (v0.2) the reports are delivered in an msi installer rather than simply a zip file as they were before, use the installer to easily make the reports available in whatever location you require:

After installation you will have a folder containing all the report project artefacts.

Open SSISReportingPack.rptproj in Visual Studio just as you would any other Reporting Services project from where you can deploy the reports to your Denali report server of choice. You will need to edit the data source (SSISCatalog.rds) to point to your SSIS Catalog (i.e. the [SSISDB] database). If you do not have your own instance of the SSIS Catalog database ([SSISDB]) but still wish to evaluate SSIS Reporting Pack I have made a copy of [SSISDB] available on SQL Azure that can be accessed using the following credentials:

Server		Username		Password	Database
enf3k2ao1m.database.windows.net		ro		r3@d0nly	SSISDB

The Reports

As I said above the reports have been changed in order to leverage the new additions to the SSIS Catalog in CTP3. The main enhancement I want to draw your attention to is the rich navigation of log data that is now provided

Notice that the log messages are now contextual, each message is shown against the executable that raised the message which in turn is indented indicating its position in the executable hierarchy. I expect this to be of great benefit when navigating package execution logs which, prior to Denali, was very difficult due to it essentially being a long flat list of messages.

SSIS Reporting Pack also has the ability to visualise the duration of each excutable:

In the simple example highlighted here by the red box we can see that iteration 3 of the For Each Loop “FEL Loop over top performing regions” took considerably longer than the two previous iterations; SSIS Reporting Pack gives us the tools we need to drill in and find out exactly where and why that slow down occurred.

Those are two of the main new features of SSIS Reporting Pack but there is lots more to discover so if you are evaluating SSIS in Denali I encourage you to download SSIS Reporting Pack and use it to learn about the plethora of data that is available in the SSIS Catalog. Please do bear in mind that this is still an early release so there are still lots of improvements to be made in the future; you can suggest improvements or report bugs either in the comments section below or (preferably) on the Discussions page at http://ssisreportingpack.codeplex.com/discussions.

@jamiet

[SSIS] OnPipelineRowsSent event

jamiet — Fri, 19 Aug 2011 11:48:00 GMT

Once upon a time I blogged at http://consultingblogs.emc.com/jamiethomson but that ended in August 2009 when I left EMC. There is a lot of valuable content over there however certain events in the past leave me concerned that that content is not well cared for and I don't have any confidence that it will still exist in the long term. Hence, I have taken the decision to re-publish some of that content here at SQLBlog so over the coming weeks and months you may find re-published content popping up here from time-to-time.
This is the first such blog post in this series in which I talk about the little-known OnPipelineRowsSent event.

An interesting discussion today on the SSIS Forum made me realise that perhaps not all SSIS developers are aware of the OnPipelineRowsSent event in SSIS and how valuable it can be, certainly when debugging data-flows. This isn't all that surprising because Books Online is very sparse in this area. Hence I thought it would make a useful blog topic.

OnPipelineRowsSent is a type of event in SSIS which means the information that it provides can be logged by whatever log provider you happen to be using. In order to understand the information that OnPipelineRowsSent provides it is critical to understand the buffer architecture of the SSIS data-flow.

To explain that VERY simply, a buffer is an area of memory that contains rows of data as they pass through the pipeline. Each data-path in the data-flow will contain one of more buffers and each of those buffers (except for the last one) will contain the same number of rows. If you want to understand more about the buffer architecture of the data-flow then Kirk Haselden's book has a chapter devoted wholly to it.

Here is what Books Online DOES say about OnPipelineRowsSent:

OnPipelineRowsSent

Reports the number of rows provided to a component input by a call to the ProcessInput method. The log entry includes the component name.

In slightly plainer english that means that for every buffer of data that is consumed by a component, you get a log entry. So, if you have (e.g.) a Derived Column Component that receives 105000 rows and the size of the buffer is 10000 rows, you'll get 11 OnPipelineRowsSent log entries for that component (there will only be 5000 rows in the last buffer). Basically it enables you to know how many rows are passing through each data-path in the data-flow.

The available information is the same as you get for any eventhandler. i.e.

event
computer
operator
source
sourceid
executionid
starttime
endtime
datacode
databytes
message

and here is a portion of a logfile containing those records:

OnPipelineRowsSent,CGOJATHOMSON,INT\Jamie.Thomson,Data Flow Task,{EB25C41A-EFE2-4902-9610-99C0309A3B59},{33B4926F-54A9-4E00-9B74-92720A2786E0},08/03/2007 20:49:56,08/03/2007 20:49:56,0,0x,Rows were provided to a data flow component as input. : : 1228 : Merge Join Output : 1225 : Union All 1 : 1226 : Union All Input 1 : 9936
OnPipelineRowsSent,CGOJATHOMSON,INT\Jamie.Thomson,Data Flow Task,{EB25C41A-EFE2-4902-9610-99C0309A3B59},{33B4926F-54A9-4E00-9B74-92720A2786E0},08/03/2007 20:49:56,08/03/2007 20:49:56,0,0x,Rows were provided to a data flow component as input. : : 1475 : Union All Output 1 : 1470 : Sort 3 : 1471 : Sort Input : 9936
OnPipelineRowsSent,CGOJATHOMSON,INT\Jamie.Thomson,Data Flow Task,{EB25C41A-EFE2-4902-9610-99C0309A3B59},{33B4926F-54A9-4E00-9B74-92720A2786E0},08/03/2007 20:49:56,08/03/2007 20:49:56,0,0x,Rows were provided to a data flow component as input. : : 1228 : Merge Join Output : 1225 : Union All 1 : 1226 : Union All Input 1 : 2085
OnPipelineRowsSent,CGOJATHOMSON,INT\Jamie.Thomson,Data Flow Task,{EB25C41A-EFE2-4902-9610-99C0309A3B59},{33B4926F-54A9-4E00-9B74-92720A2786E0},08/03/2007 20:49:56,08/03/2007 20:49:56,0,0x,Rows were provided to a data flow component as input. : : 1475 : Union All Output 1 : 1470 : Sort 3 : 1471 : Sort Input : 9936
OnPipelineRowsSent,CGOJATHOMSON,INT\Jamie.Thomson,Data Flow Task,{EB25C41A-EFE2-4902-9610-99C0309A3B59},{33B4926F-54A9-4E00-9B74-92720A2786E0},08/03/2007 20:49:56,08/03/2007 20:49:56,0,0x,Rows were provided to a data flow component as input. : : 1475 : Union All Output 1 : 1470 : Sort 3 : 1471 : Sort Input : 2085
OnPipelineRowsSent,CGOJATHOMSON,INT\Jamie.Thomson,Data Flow Task,{EB25C41A-EFE2-4902-9610-99C0309A3B59},{33B4926F-54A9-4E00-9B74-92720A2786E0},08/03/2007 20:49:56,08/03/2007 20:49:56,0,0x,Rows were provided to a data flow component as input. : : 2121 : Sort Output : 2113 : Merge Join 2 : 2114 : Merge Join Left Input : 9936

The important stuff is what comes in the last field, the message so let's break that down. Here is an example message:

Rows were provided to a data flow component as input. : : 1030 : OLE DB Source Output : 1025 : Sort 2 : 1026 : Sort Input : 9972

And here's what it is constituted of:

Rows were provided to a data flow component as input. - That's consistent in each message, so to be honest they could have left it out
1030 - ID of the data-path providing the buffer
OLE DB Source Output - Name of the data-path providing the buffer
1025 - ID of the component receiving the buffer
Sort 2 - Name of the component receiving the buffer
1026 - ID of the input receiving the buffer
Sort Input - Name of the input receiving the buffer
9972 - Number of rows in the buffer

As you can see, this information will enable you to determine exactly how many rows are output from each component. Thus, if you are not receiving the expected number of rows at a destination this event will help you to deduce where you are losing them from.

You may not know this but you actually encounter OnPipelineRowsSent every time you run a data-flow within the SSIS Designer in BIDS. Notice how the designer shows the number of rows passing through the pipeline and through each component:

How does the designer know how many rows are passing through the data-flow? Simple! Its because the SSIS Designer consumes the OnPipelineRowsSent event that the executing package "throws" up and then presents that information visually as the numbers that you see flashing in front of your eyes as the data-flow executes.

I think that just about covers the simple stuff around OnPipelineRowsSent. If you have any questions then post them here as a comment.

@Jamiet

SSIS Logging in Denali

jamiet — Sat, 16 Jul 2011 15:16:00 GMT

In my blog post SSIS Server, Catalogs, Environments & Environment Variables in SSIS in Denali from November 2010 I alluded to forthcoming enhancements in the logging infrastructure when I said:

One final note on logging. The fairly limited information that gets captured in the current CTP is not the same as what will be in the product upon release – there is a lot more to come.

I wasn’t kidding. Those logging enhancements have hit the street in CTP3 and in my opinion they are worth waiting for. SSIS logging has long been an interest of mine primarily because the logging support in SSIS has, up to now, been woeful and that’s what led me to author what has proved to be one of my more popular blog posts Custom Logging Using Event Handlers way back in June 2005. Most serious SSIS shops I come across these days have implemented their own custom logging solution and I’m happy to be able to tell them that with Denali they are no longer forced to do that. In this blog post I’ll walk you through all of the crucial objects in the SSIS Catalog related to logging and by the end of it you’ll hopefully have a good handle on the new capabilities. I assume at this point that you understand what is meant by the terms catalog, projects, parameters, executions, executables, environments, environment references, environment variables and shared connection managers in the context of SSIS; if not then I have plenty of past material that you can go and read to fill yourself in at http://sqlblog.com/blogs/jamie_thomson/archive/tags/denali/ssis/default.aspx.

To demonstrate some of the new abilities I have put together a SSIS project that contains two packages, Master.dtsx & ExportDataForCountry.dtsx:

Note also that we have a Shared Connection Manager.

The intention is to access the [AdventureWorks2008] database and find the 3 best countries with the highest number of sales for a given year. Then, for each of those 3 countries in the given year, extract the sales data and (a) sort and output to a file and (b) aggregate and insert into a table. Here are my project parameters (note the descriptions):

Here is Master.dtsx:

We use an Execute SQL Task to get the 3 top performing countries for the given year (in the “Year” project parameter) and call ExportDataForCountry.dtsx for each one of them. We also ensure that the folder (given in FolderPath project parameter) into which we are going to output the csv files exists.

Note also how I was able to take this screenshot of the whole package. This was made easier thanks to the move to Visual Studio 2010 because each open package is a pane in its own right and can be dragged out of the Visual Studio shell , then onto a second screen if you so wish. A really nice new feature.

ExportDataForCountry.dtsx consists of just one task – a dataflow:

It also has a package parameter (again, note the description):

I am going to use the logging information created by executing Master.dtsx in the rest of the blog post to demonstrate the new logging capabilities in Denali. I have used verbose logging (the highest logging level) and environment variables; here is the resultant code to execute master.dtsx:

Declare @execution_id bigint
EXEC [SSISDB].[catalog].[create_execution] 
      @package_name    =  N'Master.dtsx', 
      @execution_id    =  @execution_id OUTPUT, 
      @folder_name    =  N'CTP3', 
      @project_name    =  N'20110712 Logging Demo', 
      @use32bitruntime  =  False, 
      @reference_id    =  3
Select @execution_id
DECLARE @var0 smallint = 3
EXEC [SSISDB].[catalog].[set_execution_parameter_value] 
      @execution_id,  
      @object_type    =  50, 
      @parameter_name    =  N'LOGGING_LEVEL', 
      @parameter_value  =  @var0
DECLARE @var1 bit = 0
EXEC [SSISDB].[catalog].[set_execution_parameter_value] 
      @execution_id,  
      @object_type    =  50, 
      @parameter_name    =  N'DUMP_ON_ERROR', 
      @parameter_value  =  @var1
EXEC [SSISDB].[catalog].[start_execution] 
      @execution_id

So then, let’s dive into what actually gets logged! if you want to follow along at home then you can download the project file (i.e. .ispac file) from https://skydrive.live.com/#!/?cid=550f681dad532637&sc=documents&uc=1&id=550F681DAD532637%2115204 (you will need to have an instance of [AdventureWorksDW2008] hanging around somewhere.)

You might want to go and get yourself a drink before you continue – this one is a biggie!!

[catalog].[executions]

You are going to become very very familiar indeed with [catalog].[executions]. It is a view that provides a record of all package executions on the server and, most importantly, it contains [execution_id] – the identifier for each execution and the field to which all other objects herein will be related. There are a number of other fields in here some of which are interesting and some which are not; I suspect that you are going to be most interested in:

start_time
end_time
status

[start_time] & [end_time] are self-explanatory. [status] represents the current status of an execution and its possible values are:

created (1)
running (2)
canceled (3),
failed (4)
pending (5)
ended unexpectedly (6)
succeeded (7)
stopping (8)
completed (9)

Putting those together then we get:

SELECT execution_id,status,
CASE  WHEN [status] = 1 THEN 'created'
    WHEN [status] = 2 THEN 'running'
    WHEN [status] = 3 THEN 'canceled'
    WHEN [status] = 4 THEN 'failed'
    WHEN [status] = 5 THEN 'pending'
    WHEN [status] = 6 THEN 'ended unexpectedly'
    WHEN [status] = 7 THEN 'succeeded'
    WHEN [status] = 8 THEN 'stopping'
    WHEN [status] = 9 THEN 'completed'
END AS [status_text]
,DATEDIFF(ss,start_time,end_time)DurationInSeconds
FROM  catalog.executions e

We get some interesting operating system information in the way of total/available physical memory, total/available page file, number of available CPUs and the O/S process ID:

SELECT  execution_id,
    e.total_physical_memory_kb,
    e.available_physical_memory_kb,
    e.total_page_file_kb,
    e.available_page_file_kb,
    e.process_id
FROM  catalog.executions e
WHERE  e.[execution_id] = 10

Finally, we also get information about the environment that was used by the execution (if at all) such as the environment name and information pertaining to whether it was an absolute or relative reference (don’t worry too much about the different between an absolute or relative reference for now – its not all that important):

SELECT  e.[environment_name],e.reference_id,e.reference_type
FROM  catalog.executions e
WHERE  e.[execution_id] = 10

There are other columns in [catalog].[executions] but they’re either self-explanatory or not worth talking about here.

[catalog].[executions] is logged to when LOGGING_LEVEL is set to Verbose, Performance, Basic or None.

[catalog].[execution_parameter_values]

This view is self-explanatory – it tells us what parameter values were supplied to the package when it executed however there is probably more information in here than you may first imagine there to be. If you look at the code at the top of this blog post that executed our package you will notice that there are two calls to stored procedure [catalog].[set_execution_parameter_value] (for LOGGING_LEVEL and DUMP_ON_ERROR) thus you may assume that there would be two rows in [catalog].[execution_parameter_values]. Not so, let’s take a look:

SELECT  epv.[parameter_name],epv.[parameter_value],epv.[value_set],epv.[runtime_override]
FROM  [catalog].[execution_parameter_values] epv
WHERE  [execution_id] = 10
Fourteen rows, let’s break them down:

We know that FolderPath & Year are our project parameters yet we didn’t define a value for them when we executed. The reason for their appearance in [catalog].[execution_parameter_values] is due to the fact that (as we saw in [catalog].[executions]) this execution was executed against an environment called “2003 localhost” The project was pre-configured to get a value for “Year” from the referenced environment (hence [value_set]=1) whereas “FolderPath” was pre-configured to use the server default and hence why we had no need to supply values for them using [catalog].[set_execution_parameter_value] ([value_set]=0).

DUMP_ON_ERROR & LOGGING_LEVEL are system parameters that we supplied values for using [catalog].[set_execution_parameter_value] (hence [runtime_override]=1)

CALLER_INFO, DUMP_EVENT_CODE, DUMP_ON_EVENT & SYNCHRONIZED are further system parameters that we could have supplied values for.

The six parameters whose name begin with “CM.AdventureWorksDW2008.” are actually properties of the project’s Shared Connection Manager and by default they get logged in [catalog].[execution_parameter_values]. Notice that CM.AdventureWorksDW2008.ServerName has [value_set]=1, that is because our environment reference specified a value for that property too.

[catalog].[execution_parameter_values] is logged to when LOGGING_LEVEL is set to Verbose, Performance, Basic or None.

[catalog].[executables]

[catalog].[executables] contains a record for every single executable that gets executed in an execution. What’s an executable? It is every task, container or package in both the package that you execute and any child packages that also get executed using the Execute Package Task. Here’s what we get:

SELECT  executable_id,executable_name,package_name,package_path
FROM  [catalog].executables

We can see that all our tasks and our For Each Loop (“FEL Loop over top performing regions”) appear in here along with the containing package. Interestingly we also get package_path which provides the name of the task in the context of its location in the package.

It is worth noting that we only get a record in [catalog].[executables] if an executable actually gets executed. If that doesn’t happen (because of an earlier error or conditional control-flow) then there won’t be a record in here.

Also note that executables “ExportDataForCountry” and “DFT Export Sales for named country” have an [executable_id] that is unique across the whole execution, not just across [package_name]. In other words SSIS doesn’t care which physical .dtsx file an executable is in, it treats them all as executables in a single execution; I happen to think that is a massive step forward in Denali and you’ll see even more benefits of that in later views.

[catalog].[executables] is logged to when LOGGING_LEVEL is set to Verbose, Performance, Basic or None.

[catalog].[executable_statistics]

This is where the new logging infrastructure in Denali really starts to show benefit. For every executable in [catalog].[executables] we get information about it being executed such as whether it succeeded or not and how long it took. You might ask “Why not just put that information in [catalog].[executables]?” and actually the answer is simple when you think about it; an executable can, if it exists inside a For Loop or For Each Loop container, be executed more than once during a single execution. SSIS will capture information about each instance of an execution being executed and moreover will differentiate between each one of them. let’s take a look:

SELECT  executable_id,execution_path,execution_duration,execution_result
FROM  [catalog].[executable_statistics]
We don’t just get the name of the executable, we get its position in the container hierarchy (aka call stack). Best of all that call stack extends across different packages (remember that “Master” and “ExportDataForCountry” are the names of our two packages). We can also differentiate between different instances of an executable via the [1], [2], [3], ... suffix on our For Loop and For Each Loop iterations.

Think back to the [msdb]..[sysssislog] table prior to Denali which is just a long flat list of intermingled records and how difficult it is to find the information in there that you are after and I think you will realise the benefit of having [execution_path]. This contextual information is something I have been asking for for a long time and I am delighted that it is now available. In fact, I’ll go on record as saying that I think [execution_path] is the best new feature in SSIS in Denali, I really do. Note that [execution_path] is different to [catalog].[executables].[package_path] that we saw earlier because [package_path] only tells us the location of an executable in a package; it does not provide information in the context of an execution therefore it doesn’t extend across packages either like [execution_path] does.

We get an execution duration for every single executable (we also get start time and end time which I haven’t shown on this screenshot). Lastly we also get [execution_result] which tells us whether an executable succeeded or not – the value in [execution_result] comes from the DTSExecResult enumeration.

There is a lot of information wrapped up in just these three columns and I make heavy use of it in SSIS Reporting Pack, a suite of reports that I am putting together which provide value on top of the logged information. Here is a screenshot of a new report that leans heavily on [catalog].[executable_statistics]:

More to come on SSIS Reporting Pack in a later blog post.

[catalog].[executable_statistics] is logged to when LOGGING_LEVEL is set to Verbose, Performance, Basic or None.

[catalog].[event_messages]

[catalog].[event_messages] is the real meat of the new logging infrastructure and is where I suspect folks investigating SSIS issues will spend most of their time. It performs a very similar role to [msdb]..[sysssislog] however the information herein is much more enhanced as we shall see. It is also the table for which your choice of LOGGING_LEVEL can have the biggest affect.

The first point to make about [catalog].[event_messages] is that it does not contain [execution_id], instead it has [operation_id] which actually is an [execution_id]. The reason for the different name is that various different types of operations can occur on the SSIS Server, only one of which is package execution. Each operation will log into [catalog].[event_messages] and hence we have [operation_id] instead of [execution_id]. In this blog post the only operation type that I am covering is package execution.

The data in [msdb]..[sysssislog] was based around the notion of events, all tasks were capable of raising those events and we had the choice of capturing those events and logging them; from that perspective things are no different in Denali. We get all of the columns that we used to get in [msdb]..[sysssislog], the important ones being:

time of message
message
message source
event name
package name

SELECT  cast(message_time as datetime)message_time,message,package_name,event_name,message_source_name
FROM  [catalog].[event_messages]

In addition we also get the aforementioned [package_path] and [execution_path] which, as I already have said, are great additions:

SELECT  [message_source_name],[package_path],[execution_path]
FROM  [catalog].[event_messages]

Another new field is [subcomponent_name] which, as far as I can discern, contains the name of a dataflow component or the internal pipeline that is throwing the event. This is really useful information, previously we only got the name of the dataflow.

SELECT  subcomponent_name,message
FROM  [catalog].[event_messages]
Notice some of the information that we get here regarding rows cached and bytes of memory used, this is all really useful information to have access to.

Two other new columns are [message_type] and [message_source_type] which allow you to further drill down on the information that you are after. They appear in the view as numeric values and whilst there is no documentation publicly available yet on what these values mean I can fill you in on them right here:

First [message_type]

message_type	Description
10	OnPreValidate
20	OnPostValidate
30	OnPreExecute
40	OnPostExecute
60	OnProgress
70	OnInformation
90	Diagnostic
110	OnWarning
140	DiagnosticEx
200	Custom events
400	OnPipeline*

and [message_source_type]

message_source_type	Description
10	Messages logged by the entry APIs (e.g. T-SQL, CLR Stored procedures)
20	Messages logged by the external process used to run package (ISServerExec)
30	Messages logged by the package-level objects
40	Messages logged by tasks in the control flow
50	Messages logged by containers (For, ForEach, Sequence) in the control flow
60	Messages logged by the Data Flow Task

As I alluded to above your choice of LOGGING_LEVEL greatly influences the amount of information that gets logged. I ran this package against each of the four logging levels and here are the number of rows in [catalog].[event_messages]:

LOGGING_LEVEL	Rows	Time to Execute (seconds)
None	0	4
Basic	128	3
Performance	1	10
Verbose	2726	12

Given that this execution only contains 5 task executions and one For Each Loop, 2726 records for LOGGING_LEVEL=Verbose strikes me as being extravagant and indeed this is reflected in the much higher execution time. These numbers are not representative of your environment and of course you should do your own testing accordingly but it does seem as though LOGGING_LEVEL=Verbose can have a detrimental affect on execution duration. If you take a look at the messages that get logged from Verbose logging it is clear that this is intended to be used for diagnostic purposes; messages such as the following aren’t the sort that you want to be wading through on a regular basis:

Interestingly [message_source_name] for all these messages is ‘AdventureWorksDW2008’ which is the name of our Connection Manager so it seems as though LOGGING_LEVEL=Verbose may be a shorthand way of telling SSIS to log all information pertaining to resources external to the package.

I have noticed some interesting new messages when LOGGING_LEVEL=Verbose too that I don’t remember ever seeing before:

Lots of useful information in there, I particularly like that we get a message for each executable telling us its execution duration. Yes, this information is in [catalog].[executable_statistics] as we have already discussed but its useful to have that information in our main log table too.

As you can see [catalog].[event_messages] is the workhorse of the new logging infrastructure so its worth spending time getting to know it. Similar to [catalog].[executable_statistics] I make heavy use of this table in SSIS Reporting Pack and the existence of [execution_path] makes it easy to browse to the messages that you want to see:

We can highlight errors and warnings much more clearly too:

[catalog].[executable_statistics] is logged to when LOGGING_LEVEL is set to Verbose, Performance or Basic. For LOGGING_LEVEL=Performance only OnError and OnWarning events get logged. For LOGGING_LEVEL=Basic OnError, OnInformation, OnPreExecute, OnPostExecute, OnPreValidate, OnPostValidate and OnWarning events are logged however as I demonstrated above less OnInformation events are logged than for LOGGING_LEVEL=Verbose.

[catalog].[event_message_context]

Have you ever wanted to know what the properties of an executing package were after the event? That is exactly what [catalog].[event_message_context] is provided for. For a very small subset of the messages in [catalog].[event_messages] it logs properties of the package and its connection managers at the point-in-time that the message is logged. The properties are logged as name:value pairs. This is all better illustrated with a screenshot:

SELECT  em.[message],emc.[package_path],emc.[property_name],emc.[property_value]
FROM  [catalog].[event_message_context] emc
inner join [catalog].[event_messages] em on emc.[event_message_id] = em.[event_message_id]

[catalog].[event_message_context] is logged to at the start of a package execution at which point it tells you all the properties of the package. This is useful (I guess) but more useful than that is the logging of properties when an OnError event occurs; more accurately, [catalog].[event_message_context] will record all the properties of a failed task. To demonstrate I shutdown the server hosting the [AdventureWorks2008DW] database prior to executing our package and here is a subset of what gets logged in [catalog].[event_message_context]:

SELECT  emc.[context_source_name],emc.[property_name],emc.[property_value]
FROM  [catalog].[event_message_context] emc 
INNER JOIN [catalog].[event_messages] em 
  on emc.event_message_id = em.event_message_id 
WHERE  em.operation_id = 19 
AND    em.event_name = 'OnError'
AND    [property_name] IN ('Connection','StartTime','StopTime','SqlStatementSource')

As you can see we get the actual SQL statement that was being executed which is invaluable information if the SQL statement is being built dynamically using an expression or a Script Task. Prior to Denali we simply did not have access to this sort of information and is a great example of how logging has been massively enhanced. Moreover we also get StartTime and StopTime so it is easy to see, at a glance, how long it took the task to fail. I find it interesting to note that StartTime and StopTime are execution-time-only properties, but they still get logged. I wonder what other execution-time-only properties exist? If you find any do let me know!

One final thing to note is that when an error occurs [catalog].[event_message_context] will contain information about every object in the call stack so if, for example, an Execute SQL Task that is inside a For Each loop fails you will get information about the For Each loop too. Very cool!

[catalog].[event_message_context] is logged to when LOGGING_LEVEL is set to Verbose, Performance and Basic.

[catalog].[execution_component_phases]

If you have ever wanted to know which parts of a dataflow are running slowly then [catalog].[execution_component_phases] is for you. It records how long each data flow component spends in each phase of execution, those phases are:

Validate
PrepareForExecute
PreExecute
ProcessInput
PrimeOutput
PostExecute
Cleanup

The most obvious use of this view is simply to discover where the bottlenecks are in your dataflows by discovering which components take the longest time to complete. Before we look at the information in [catalog].[execution_component_phases] let’s remind ourselves of the dataflow that we’re going to examine here:

There are nine components, let’s look at how long each of them is “alive” for during the execution of this dataflow:

SELECT  q2.[subcomponent_name],q2.[phase_time_milliseconds]
FROM  (
    SELECT  q.[subcomponent_name],DATEDIFF(ms,q.[min_start_time],q.[max_end_time])[phase_time_milliseconds]
    FROM  (
        SELECT  [subcomponent_name],MIN([start_time])[min_start_time],MAX([end_time])[max_end_time]
        FROM  [catalog].execution_component_phases
        where  [execution_path] = @execution_path
        group  by [subcomponent_name]
        )q
    )q2
ORDER BY q2.[phase_time_milliseconds] DESC

Here we see that LKP Get Customer details has spent the most time executing. To be honest though this query does not give us the best indication of where the bottlenecks are because it includes all phases; the Validate phase will begin at roughly the same time for all components whereas the Cleanup phase for each will end at roughly the same time as well. A better indicator would be to look at the ProcessInput and PrimeOutput phases because this is generally where most of the work is done:

SELECT  q2.[subcomponent_name],q2.[phase_time_milliseconds]--,q2.[min_start_time],q2.[max_end_time]
FROM  (
    SELECT  q.[subcomponent_name],q.[min_start_time],q.[max_end_time],DATEDIFF(ms,q.[min_start_time],q.[max_end_time])[phase_time_milliseconds]
    FROM  (
        SELECT  [subcomponent_name],MIN([start_time])[min_start_time],MAX([end_time])[max_end_time]
        FROM  [catalog].execution_component_phases
        where  [execution_id] = @verbose
        and    [execution_path] = @execution_path
        and    phase in ('ProcessInput','PrimeOutput')
        group  by [subcomponent_name]
        )q
    )q2
ORDER BY q2.[phase_time_milliseconds] DESC

Here we get a much better indicator of where time is spent and where the bottlenecks are in our dataflow. Unsurprisingly the destination component that inserts data into the database takes the longest time to complete its work however look at the next three, the Sort component, the Aggregate component and the OLE DB Source component; these three components are all asynchronous so the information that we are seeing here supports the common held belief that asynchronous components are generally slower.

Also notice that Multicast is the shortest to execute. Again not surprising given that Multicast components don’t actually do any work.

We have two derived column components (“DER Concat Full Name” & “DER Calculate TotalPrice”) yet one of them takes a lot less time than the other. Again this makes sense if we look at our dataflow; “DER Concat Full Name” occurs after the Aggregate component thus it will almost certainly be operating on less rows. Less rows means less work to do means less time to execute.

As an aside, [catalog].[execution_component_phases] makes it easy to determine exactly which components are asynchronous because they are the ones that have a PrimeOutput phase:

SELECT  q2.[subcomponent_name],q2.[phase_time_milliseconds]--,q2.[min_start_time],q2.[max_end_time]
FROM  (
    SELECT  q.[subcomponent_name],q.[min_start_time],q.[max_end_time],DATEDIFF(ms,q.[min_start_time],q.[max_end_time])[phase_time_milliseconds]
    FROM  (
        SELECT  [subcomponent_name],MIN([start_time])[min_start_time],MAX([end_time])[max_end_time]
        FROM  [catalog].execution_component_phases
        where  [execution_id] = @verbose
        and    [execution_path] = @execution_path
        and    phase in ('PrimeOutput')
        group  by [subcomponent_name]
        )q
    )q2
ORDER BY q2.[phase_time_milliseconds] DESC

OK, so we have seen that the asynchronous components and the destination component that inserts into a database generally take the longest in the “work” phases however there are other insights to be had here. If we take a look at the PreExecute phase:

SELECT  q2.[subcomponent_name],q2.[phase_time_milliseconds]--,q2.[min_start_time],q2.[max_end_time]
FROM  (
    SELECT  q.[subcomponent_name],q.[min_start_time],q.[max_end_time],DATEDIFF(ms,q.[min_start_time],q.[max_end_time])[phase_time_milliseconds]
    FROM  (
        SELECT  [subcomponent_name],MIN([start_time])[min_start_time],MAX([end_time])[max_end_time]
        FROM  [catalog].execution_component_phases
        where  [execution_id] = @verbose
        and    [execution_path] = @execution_path
        and    phase in ('PreExecute')
        group  by [subcomponent_name]
        )q
    )q2
ORDER BY q2.[phase_time_milliseconds] DESC

we notice that our lookup component (“LKP Get customer details”) appears much higher in the list than it did previously. This is not surprising given that this is a fully cached lookup component and the PreExecute phase is when that cache gets populated.

Clearly there are many many insights to be gleaned from [catalog].[execution_component_phases] and it should prove to be an invaluable tool when performance tuning dataflows.

[catalog].[execution_component_phases] is logged to when LOGGING_LEVEL is set to Verbose and Performance.

[catalog].[execution_data_statistics]

Where [catalog].[execution_component_phases] tells us how long each component executed for, [catalog].[execution_data_statistics] tells us how much data they processed. I’m sure that if you have ever executed packages in BIDS and made use of the real-time rowcounts that appear in the GUI:

then at some point you will have wished that you had the same outside of BIDS too; well, that is exactly what [catalog].[execution_data_statistics] provides. Every time a dataflow component passes a buffer on to the next component then you will get a record in [catalog].[execution_data_statistics]. Specifically you will get the following information:

execution_path of the containing dataflow (we’ve covered this quite a bit already)
dataflow path id (a meaningful unique identifier for each data path in the dataflow)
source component (the component passing the buffer on)
destination component (the component receiving the buffer)
time that the buffer was passed on
number of rows in the buffer

Here’s what that looks like for our dataflow:

SELECT  eds.[dataflow_path_id_string],eds.[rows_sent],eds.[created_time]
FROM  [catalog].[execution_data_statistics] eds
WHERE  eds.[execution_path] = @execution_path
ORDER  BY [dataflow_path_id_string]

Of course once you have the raw data then you can party on it as much as you want. Remember that [catalog].[execution_data_statistics] has a record for each buffer, not for each datapath and hence to get a total per datapath you’re going to need to SUM:

SELECT  eds.[dataflow_path_id_string],SUM(eds.[rows_sent])[total_rows_sent],MIN(eds.[created_time])[first_buffer_sent],MAX(eds.[created_time])[last_buffer_sent]
FROM  [catalog].[execution_data_statistics] eds
WHERE  eds.[execution_path] = @execution_path
GROUP  BY [dataflow_path_id_string]

[catalog].[execution_data_statistics], along with [catalog].[execution_component_phases], seems set to be an integral part of your dataflow performance tuning armoury.

[catalog].[execution_data_statistics] is logged to when LOGGING_LEVEL is set to Verbose.

That concludes this run through of the new logging capabilities in SQL Server Denali CTP3. I personally am very happy indeed with these enhancements and am looking forward to building new solutions on this infrastructure as soon as possible. How about you? Are these new capabilities what you have been waiting for or are they superfluous to your needs? Let me know in the comments.

@Jamiet

SSIS enhancements in Denali CTP3

jamiet — Tue, 12 Jul 2011 20:32:00 GMT

The third Community Technology Preview (CTP3) of SQL Server code-named Denali is upon us and, although you would never guess from the official announcement, there is a whole raft of enhancements to SQL Server Integration Services (SSIS) and in this blog post I will take you on a tour of some of them. I must stress that nothing here is finalised and anything is liable to be changed prior to the full release of Denali. Wanna know what’s new? Read on…

Parameterize a Task

If you have experienced CTP1 then you will know that one of the big new features in Denali is Parameters (if you know nothing of Parameters then you may want to take a read of my earlier post Parameters in SSIS in Denali from November 2010). In CTP3 there is a new designer enhancement that makes it a lot easier to work with parameters – right-clicking on a task shows a “Parameterize…” option:

Clicking that launches the Parameterize dialog:

In the screenshot above I am parameterizing the WorkingDirectory property of an Execute Process Task. From this dialog we have the option to:

Create a new parameter
Use an existing parameter
Initialise a newly created parameter with some value
Define a newly created parameter as package or project scoped
Define a newly created parameter as required or not

Once the parameter has been specified an expression will be placed onto the selected property setting it to the value of the parameter:

Package Parameters Tab

Package-scoped Parameters now have their own tab within the designer whereas in CTP1 they were shoehorned into the Variables pane:

Shared Connection Managers

This is one of the big-ticket features in CTP3. Connection Managers are no longer confined to a package, they can live as part of the project and be used by multiple packages. They will appear alongside package-scoped Connection Managers in the familiar Connection Manager tray in *all* packages within that project. Currently the visual differentiation between a package-scoped and a project-scoped Connection Manager is that the project-scoped Connection Manager appears in bold text:

A project-scoped Connection Manager can be used wherever you you can use a package-scoped Connection Manager.

When a project containing a Shared Connection Manager is deployed to the server then any property of that Shared Connection Manager can be changed just like a Project Parameter can be.

In the screenshot immediately above you can see that I am setting the ConnectionString property of a Shared Connection Manager to the value of an environment variable called ConnStr (for more on environments and environment variables go take a read of SSIS Server, Catalogs, Environments, Environment Variables in SSIS in Denali).

The last related point here is to note that the Data Sources and Data Source Views folders that appeared in Solution Explorer in SSIS2008R2:

have disappeared, and I am sure they will not be missed.

Project Parameters node in Solution Explorer

Project Parameters now have their own node in Solution Explorer rather than being hidden underneath a right-click menu like they were in CTP1.

Expression Indicator

Variables, Connection Managers and Tasks now have an fx adorner applied to them indicating that there is at least one expression on that object (yes, just like what BIDS Helper does for earlier versions).

Change variable scope

One of the biggest annoyances in the previous SSIS Designer was that the scope of a variable could not be changed. Not anymore, in Denali it is possible to change the scope of a variable:

Double-click to add a task

Its not really possible to demo this one with a screenshot but its pretty easy to explain. Double-clicking on a task in the toolbox will add it to the container that currently has the focus (which may of course be the package). This works for components in the data flow too.

Sort by name

It is now possible to sort packages alphabetically in Solution Explorer:

Note how the position of “Package.dtsx” & “Another Package.dtsx” has been reversed.

Simplified Data Viewers

Have you ever got annoyed that adding a data viewer takes far too many clicks given that you do the same thing (Add->Grid->Grid Tab->OK) every time? In Denali its a lot easier; there is only one option – Grid (did you every use anything else anyway?) and all columns are automatically selected:

4000 character limit on expressions has gone way

This one is pretty significant. In SSIS2008 an expression of REPLICATE(“a”,4001) times would result in design-time warnings and execution-time errors:

In Denali the 4000 character limit has gone away.

New expression language functions

We have three new functions in the expression language:

LEFT(<string>, <number-of-chars>) – A shorthand way of writing SUBSTRING(<string>, 1, <number-of-chars>)
TOKEN(<string>, <delimiter>, N) – Returns the Nth token in <string> when it is split by <delimiter>
TOKENCOUNT(<string>, <delimiter>) – Returns the total number of tokens in <string> as determined by <delimiter>

TOKEN(,,) will be particularly useful when manually parsing columns from a flat file. When used in conjunction with TOKENCOUNT it can be used to return the last token in a string like so:

TOKEN( [SomeTextColumn], “,”, TOKENCOUNT([SomeTextColumn], “,”) )

I guess they do sometimes read Connect

Different style of Success/Failure Indicator

In SSIS2008R2:

And now in Denali:

A little more understated in Denali I think you’ll agree although I suspect some people will prefer the old way! I am undecided. Arguably an icon is better than a change in colour for those that suffer from colour-blindness.

Load files with multiple row formats

One of the big complaints about SSIS over the past six years is that it has poor support for loading files where rows can have variable numbers of columns. The typical way of dealing with this was to use the Ragged Right feature and parse out the columns in a Derived Column component however that is no longer necessary – SSIS can now parse all of the columns from such files in the Flat File Source Adapter. Here is one such file that has differing row formats:

It is a simplistic example of a file that contains both OrderHeader and OrderDetails records. The OrderHeader records consist of an OrderId and a Name, the OrderDetails records consist of an OrderId, an OrderLineNumber, a ProductName and a Quantity. In the Preview screen of the Flat File Connection Manager we can see that SSIS is able to parse both of these row formats:

Typically you could then use a Conditional Split component to split the dataset into Header and Detail records:

Script out from the GUI now wired up

In earlier CTPs the Script button on the various GUIs in the SSIS Catalog didn’t do anything

In CTP3 however these are now wired up correctly so hitting CTRL+Shift+N will (in this example) produce a script containing the code required to execute a package:

Logging Level

In Denali logging is no longer configured within a package, it is done on the SSIS Server (much more on this in an upcoming blog post). This much we already knew (learn more at SSIS Server, Catalogs, Environments & Environment Variables in SSIS in Denali) however in CTP3 we now have the option to choose what data gets logged. There are four options here; None, Basic, Performance & Verbose

I won’t cover each choice here as there will be plenty of documentation available around this, for now just know that the option is available.

Data Taps

Data Taps are an exciting new feature coming in Denali and have taken me completely by surprise. Ever wanted to to view the data in an executing package like you can using a data viewer in BIDS? That is what data taps provide. You don’t have to build them into your package either, they are added on the server when the package is executed.

Data taps are worthy of a post of their own so I’ll cover them separately if no-one else does so first.

Expression Task

I once wrote a blog post entitled Nesting variables to calculate values where I opined that (where possible) it was better to build variable values dynamically using expressions rather than assign a value using a Script Task because this resulted in less executables in your package. Some people in the comments disagreed with me partly because they liked the explicitness of a task to do this job and for those people there is a new task in Denali that is right up their street – the Expression Task. Put simply the Expression task will assign the result of an expression to a variable, in the example below I am assigning a value to a variable called “Sum”

I have to be honest and say I despise this task. The variable being assigned to should be available in a dropdown box, you shouldn’t have to type it. Furthermore if they are not going to provide the variable in a dropdown then the box in which you type should not be labelled “Expression”, it should be labelled “Assignment” – because that is what it is. I will not be going anywhere near this thing, will you?

On the plus side they have moved the system variables into a “System variables” node in the “Variables and Parameters” tree which is a most welcome change.

Wrap-up

I haven’t covered everything that’s new in CTP3 but this is the bulk of it from a pure development perspective. What out of that little lot most excites you? Let me know in the comments.

I’ll touch on some other things in upcoming blog posts including an enhancement which is seemingly very insignificant but which actually excites me more than anything I’ve talked about here. Watch this space.

@jamiet

Other blog posts related to SSIS in Denali CTP3:

Microsoft SQL Server code-named 'Denali' - Community Technology Preview 3 by Joost van Rossum
SSIS - What’s New in SQL Server Denali by Matt Masson

New SSIS features and enhancements in Denali – a webinar on 28th June in association with Pragmatic Works

jamiet — Mon, 27 Jun 2011 21:39:45 GMT

Tomorrow I shall be presenting a webinar entitled “New SSIS features and enhancements in Denali”. The webinar is being hosted by Pragmatic Works and you can sign up for it at Pragmatic Works webinars. The webinar will start at 1930BST and you can view the time for your timezone at this link: http://www.timeanddate.com/worldclock/fixedtime.html?msg=New+SSIS+features+and+enhancements+in+Denali&iso=20110628T1830

The webinar was arranged a few months ago and at that time we were hoping that the next Community Technology Preview (CTP) of SQL Server Denali would be available for public consumption; unfortunately it transpires that that is not yet the case and hence I will be presenting new features of CTP1 that was released at the start of this year. If you’re not yet familiar with the new features of SSIS that are coming in the next release of SQL Server then please do come and join the webinar.

@Jamiet

Have SSIS' differing type systems ever caused you problems?

jamiet — Mon, 14 Mar 2011 16:46:00 GMT

One thing that has always infuriated me about SSIS is the fact that every package has three different type systems; to give you an idea of what I am talking about consider the following:

The SSIS dataflow's type system is made up of types called DT_* (e.g. DT_STR, DT_I4)
The SSIS variable type system is based on .Net datatypes (e.g. String, Int32)
The types available for Execute SQL Task's parameters are based on something else - I don't exactly know what (e.g. VARCHAR, LONG)

Speaking euphemistically ... this is not an optimum situation (were I not speaking euphemistically I would be a lot ruder) and hence I have submitted a suggestion to Connect at [SSIS] Consolidate three type systems into one requesting that it be remedied. This accompanying blog post is not however a request for votes (though that would be nice); the reason is actually subtler than that. Let me explain.

I have been submitting bugs and suggestions pertaining to SSIS for years and have, so far, submitted over 200 Connect items. If that experience has taught me anything it is this - Connect items are not generally actioned because they are considered "nice to have". No, SSIS Connect items get actioned because they cause customers grief and if I am perfectly honest I must admit that, other than being a bit gnarly, SSIS' three type system architecture has never knowingly caused me any significant problems.

The reason for this blog post is to ask if any reader out there has ever encountered any problems on account of SSIS' three type systems or have you, like me, never found them to be a problem? Errors or performance degredation caused by implicit type conversions would, I believe, present a strong case for getting this situation remedied in a future version of SSIS so if you HAVE encountered such problems I would encourage you to leave a comment on the Connect submission accordingly. Let me know in the comments too - I would be interested to hear others' opinions on this.

@Jamiet