A blog about SQL Server, SSIS, C# and whatever else I happen to be dealing with in my professional life.

Find ramblings

Thursday, February 10, 2011

Deadlocks and you

Or "What I learned today." What I didn't learn, was how to resolve deadlocks. What I did learn via a crash course of forums, blog posts, BOL and tweets was how to start collecting the information that tomorrow should lead to resolution. This post will attempt to demonstrate the techniques I got to use today.

Backstory

I work in the financial services sector and we get files in from Pershing and every quarter it seems they make changes to those files. I'm sure in the mainframe world, files with different record types make sense but good grief, they are not exactly pleasant in my world. For these files, they are all a fixed length but based on some information in the first N characters of the file, it will determine how the rest of that line should be parsed. Our process has been implemented and running fine for a few years and a minor change (defined column lengths) by a coworker causes this SSIS package to start throwing deadlocks. What's curious though, is that the only thing active in that database is the SSIS package itself. None-the-less, it was consistently throwing "Transaction (Process ID N) was deadlocked on generic waitable object resources with another process and has been chosen as the deadlock victim." What was slightly odd was that the exact tables being blocked varied between runs.

Below is a simplistic version of the SSIS package we used to load tables. There are record types A-V (with some letters missing in between) and the file itself is fairly small---750 characters wide and tens of thousands of rows in our file. There are no lookups or anything that talks to the database but the destination writers. They are the SQL Server Destination components and truth be told we've had more oddities with their behaviour (timeouts, unable to prepare component, etc) than the standard OLE DB component than I care to think about.

From World of Whatever
The tables we dump the data into are also simple. They are all chars defined exactly as wide as they are in the corresponding Pershing standard file layout plus an identity column and an insert date. No triggers, no foreign key, nothing that you couldn't do in Access. Only index is the clustered primary key which is the identity column. As I script it out, I am surprised to see that they do have a default constraint applied to the Insert date. As a general rule, we don't do that here. It shouldn't have any bearing on the issue as we explicitly provide a value for the insert date for all the rows going in.

Deadlock

A minor change suddenly causes "Transaction (Process ID N) was deadlocked on generic waitable object resources with another process and has been chosen as the deadlock victim" to rear its head. The only thing running at that time is the package itself, two unrelated tables so there shouldn't be contention on the resource but there was. My DBAs are busy so I start looking. My initial results indicated I'd have entries in my SQL Server log but no such luck.

The first good clue of where to go was a post by tkizer on SQLTeam. She suggested turning on the trace flag 1222 and keeping an eye on the server log until the deadlock was encountered. That's easy enough as we could reproduce on demand. And new thing #1, I get to set a trace flag.

-- this will turn on a trace flag for capturing deadlock information
dbcc traceon(1222,-1)
Co-worker reran the SSIS package and voila, I have data. The problem to the novice is that there is now plenty of information in the server log but it didn't mean a thing to me. I suspect it's an acquired art, much like reading text query plans.

The next thing I saw references to was that deadlock graphs could also help and that new thing #2 for me. I had used Profiler before to capture SQL statements but deadlock graphs sounded intriguing and dumbed down enough for a caveman-developer to understand. I fired up Profiler and started going through my available trace templates. Nothing there for a Deadlock type, nothing that even sounded promising but then I scrolled up and saw Blank.

From World of Whatever
Blank profile
From World of Whatever
Locks, deadlock graph
From World of Whatever
Event extraction settings aka save to xml
From World of Whatever

With Profiler running, my friend kicked off the package again and just like the first time I saw SSMS display geography results, I got all excited to see the deadlock graph show me what was killed plus the victor. That's what I couldn't decipher from the original text in the SQL Server log. Ok, so armed with the knowledge that an insert into table F deadlocked the insert into table A, I started asking the twitterverse. Much love to all for their thoughts on the matter. Buck Woody @buckwoody, asked about indexes first and then suggested I turn on the trace flag to look for references/triggers. *internet fist bump for having already captured that data* He indicated the spid and ecid would give me the transaction that blocked. I had different spids but the same ecid. I left it at I need to get "the text of spid 97 and 109 to find out why" there was a deadlock. I think I have those statements captured, they're BULK INSERTs but I was going to go exploring DMVs ^H^H^H^H DMOs to see how I could find that text. It feels like something I should have picked up at Grant Fritchey's SQL PASS 2009 session but that's been many moons ago.

At this point, I get the bright idea to modify the trace to also capture sql batch statements so I know that I have the text that went along with the SPIDs. I run the package as coworker had left for the day and it worked just fine, no deadlocks. No clue what or why it worked but I'll have him rerun tomorrow to see if it's magically cleared up. Otherwise, I'll have my DBA with me to go over the database log and the nifty xdl I captured.

2011-02-09 15:42:37.00 spid62      SQL Trace ID 2 was started by login "angband\BFellows".
2011-02-09 15:43:00.01 spid15s     deadlock-list
2011-02-09 15:43:00.01 spid15s      deadlock victim=process81607588
2011-02-09 15:43:00.01 spid15s       process-list
2011-02-09 15:43:00.01 spid15s        process id=processbaf198 waittime=2359 schedulerid=1 kpid=728 status=suspended spid=102 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.640 lastbatchcompleted=2011-02-09T15:42:56.637 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000acbb503b5e346c7f243cbc90fa01d32dd4f3422b
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_P_U]
FROM 'Global\DTSQLIMPORT              000000000000176400000000207f93d0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_P_U]
FROM 'Global\DTSQLIMPORT              000000000000176400000000207f93d0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=processbaf438 waittime=2296 schedulerid=1 kpid=4564 status=suspended spid=104 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.703 lastbatchcompleted=2011-02-09T15:42:56.703 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000cd99a926d93018484c365a40ec460630f483e7c6
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_S_U]
FROM 'Global\DTSQLIMPORT              000000000000058000000000207f9470'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_S_U]
FROM 'Global\DTSQLIMPORT              000000000000058000000000207f9470'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=processbaf978 waittime=2453 schedulerid=1 kpid=5932 status=suspended spid=99 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.547 lastbatchcompleted=2011-02-09T15:42:56.543 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000993ca006fc02ea01f7eba930d1d391c6ae7e1569
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_H_U]
FROM 'Global\DTSQLIMPORT              00000000000014b000000000207f91f0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_H_U]
FROM 'Global\DTSQLIMPORT              00000000000014b000000000207f91f0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=processbafac8 waittime=2390 schedulerid=1 kpid=5284 status=suspended spid=101 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.607 lastbatchcompleted=2011-02-09T15:42:56.603 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x020000004bf48a2e308087155bbb2d611fec9cf7386371e1
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_J_U]
FROM 'Global\DTSQLIMPORT              0000000000000e4800000000207f91a0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_J_U]
FROM 'Global\DTSQLIMPORT              0000000000000e4800000000207f91a0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=processbafeb8 waittime=2500 schedulerid=1 kpid=1160 status=suspended spid=98 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.500 lastbatchcompleted=2011-02-09T15:42:56.497 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x0200000096dc761041f3f1a153d25f4d33e849ea1c229751
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_G_U]
FROM 'Global\DTSQLIMPORT              0000000000000e0400000000207f9240'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_G_U]
FROM 'Global\DTSQLIMPORT              0000000000000e0400000000207f9240'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81606088 waittime=2328 schedulerid=1 kpid=6028 status=suspended spid=103 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.677 lastbatchcompleted=2011-02-09T15:42:56.677 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x020000005133cd14ef9ee1a6f03cba5deff4ad3c54b8e728
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_R_U]
FROM 'Global\DTSQLIMPORT              000000000000164c00000000207f9420'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_R_U]
FROM 'Global\DTSQLIMPORT              000000000000164c00000000207f9420'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process816061d8 waittime=2234 schedulerid=1 kpid=3696 status=suspended spid=106 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.770 lastbatchcompleted=2011-02-09T15:42:56.770 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x020000007edc28250efbf55e25703f1213376177506ce422
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_U_U]
FROM 'Global\DTSQLIMPORT              00000000000016c000000000207f9510'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_U_U]
FROM 'Global\DTSQLIMPORT              00000000000016c000000000207f9510'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81606328 waittime=2593 schedulerid=1 kpid=6072 status=suspended spid=95 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.400 lastbatchcompleted=2011-02-09T15:42:56.400 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x020000004ef6d2222660683168a240c08cff5cf21486794d
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_D_U]
FROM 'Global\DTSQLIMPORT              00000000000013ec00000000207f9100'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_D_U]
FROM 'Global\DTSQLIMPORT              00000000000013ec00000000207f9100'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81606478 waittime=2640 schedulerid=1 kpid=5784 status=suspended spid=94 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.370 lastbatchcompleted=2011-02-09T15:42:56.367 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000f65cb11c4311f1c6c775d0a257a256408087c377
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_C_U]
FROM 'Global\DTSQLIMPORT              0000000000000ffc00000000207f90b0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_C_U]
FROM 'Global\DTSQLIMPORT              0000000000000ffc00000000207f90b0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81606868 waittime=2171 schedulerid=1 kpid=2772 status=suspended spid=108 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.830 lastbatchcompleted=2011-02-09T15:42:56.827 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x0200000012ae6533ee4da6cbcbeeedf8980d82432a718b44
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_X_U]
FROM 'Global\DTSQLIMPORT              00000000000012c80000000020d064d0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_X_U]
FROM 'Global\DTSQLIMPORT              00000000000012c80000000020d064d0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process816069b8 waittime=2671 schedulerid=1 kpid=5244 status=suspended spid=93 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.330 lastbatchcompleted=2011-02-09T15:42:56.330 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000e7411722be42a388bbd9a9b195246bb841885e60
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_B_U]
FROM 'Global\DTSQLIMPORT              0000000000000e6000000000207f92e0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_B_U]
FROM 'Global\DTSQLIMPORT              0000000000000e6000000000207f92e0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81607048 waittime=2203 schedulerid=1 kpid=1580 status=suspended spid=107 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.797 lastbatchcompleted=2011-02-09T15:42:56.793 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000156b232ad7ff49fec4fcb0049f385831639128ee
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_V_U]
FROM 'Global\DTSQLIMPORT              000000000000061000000000207f9560'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_V_U]
FROM 'Global\DTSQLIMPORT              000000000000061000000000207f9560'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81607198 waittime=2562 schedulerid=1 kpid=2964 status=suspended spid=96 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.437 lastbatchcompleted=2011-02-09T15:42:56.433 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x0200000098958b21cb131547c31c4d8e75e2b2052e0935c4
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_E_U]
FROM 'Global\DTSQLIMPORT              000000000000088000000000207f9380'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_E_U]
FROM 'Global\DTSQLIMPORT              000000000000088000000000207f9380'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81607588 taskpriority=0 logused=20000 waittime=3078 schedulerid=1 kpid=5348 status=suspended spid=109 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.890 lastbatchcompleted=2011-02-09T15:42:56.890 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000cf3190043adc64beec0889c3296470d20f320047
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_A_U]
FROM 'Global\DTSQLIMPORT              00000000000005dc0000000020d06520'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_A_U]
FROM 'Global\DTSQLIMPORT              00000000000005dc0000000020d06520'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process816076d8 waittime=2421 schedulerid=1 kpid=4384 status=suspended spid=100 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.580 lastbatchcompleted=2011-02-09T15:42:56.580 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x020000001d15a4063c634d99bbf604a010f5c33fad397ddb
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_I_U]
FROM 'Global\DTSQLIMPORT              0000000000000d4000000000207f9290'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_I_U]
FROM 'Global\DTSQLIMPORT              0000000000000d4000000000207f9290'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81607978 waittime=2265 schedulerid=1 kpid=5492 status=suspended spid=105 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.740 lastbatchcompleted=2011-02-09T15:42:56.737 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x020000004a242209b9807aea92debd24a258c1cff4f75c83
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_T_U]
FROM 'Global\DTSQLIMPORT              00000000000008a800000000207f94c0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_T_U]
FROM 'Global\DTSQLIMPORT              00000000000008a800000000207f94c0'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s        process id=process81607c18 waittime=2546 schedulerid=1 kpid=2864 status=suspended spid=97 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2011-02-09T15:42:56.457 lastbatchcompleted=2011-02-09T15:42:56.457 clientapp=Microsoft SQL Server hostname=WADDSQL0 hostpid=2400 loginname=angband\waddsql0_sql isolationlevel=serializable (4) xactid=13600869 currentdb=17 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
2011-02-09 15:43:00.01 spid15s         executionStack
2011-02-09 15:43:00.01 spid15s          frame procname=adhoc line=1 sqlhandle=0x02000000207530087f4046c20711bb850257b8626e738061
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_F_U]
FROM 'Global\DTSQLIMPORT              000000000000104400000000207f9150'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)     
2011-02-09 15:43:00.01 spid15s         inputbuf
2011-02-09 15:43:00.01 spid15s     BULK INSERT [dbo].[PRSHG_ACCT_REC_F_U]
FROM 'Global\DTSQLIMPORT              000000000000104400000000207f9150'
WITH (DATAFILETYPE = 'DTS_Buffers', CODEPAGE = 'RAW', CHECK_CONSTRAINTS, TABLOCK)    
2011-02-09 15:43:00.01 spid15s       resource-list
2011-02-09 15:43:00.01 spid15s        resourceWait
2011-02-09 15:43:00.01 spid15s         owner-list
2011-02-09 15:43:00.01 spid15s          owner id=process81607c18
2011-02-09 15:43:00.01 spid15s          owner id=process81607978
2011-02-09 15:43:00.01 spid15s          owner id=process816076d8
2011-02-09 15:43:00.01 spid15s          owner id=process81607198
2011-02-09 15:43:00.01 spid15s          owner id=process81607048
2011-02-09 15:43:00.01 spid15s          owner id=process816069b8
2011-02-09 15:43:00.01 spid15s          owner id=process81606868
2011-02-09 15:43:00.01 spid15s          owner id=process81606478
2011-02-09 15:43:00.01 spid15s          owner id=process81606328
2011-02-09 15:43:00.01 spid15s          owner id=process816061d8
2011-02-09 15:43:00.01 spid15s          owner id=process81606088
2011-02-09 15:43:00.01 spid15s          owner id=processbafeb8
2011-02-09 15:43:00.01 spid15s          owner id=processbafac8
2011-02-09 15:43:00.01 spid15s          owner id=processbaf978
2011-02-09 15:43:00.01 spid15s          owner id=processbaf438
2011-02-09 15:43:00.01 spid15s          owner id=processbaf198
2011-02-09 15:43:00.01 spid15s         waiter-list
2011-02-09 15:43:00.01 spid15s          waiter id=process81607588
2011-02-09 15:43:00.01 spid15s        TransactionMutex
2011-02-09 15:43:00.01 spid15s         TransactionInfo Workspace=2246939568
2011-02-09 15:43:00.01 spid15s         owner-list
2011-02-09 15:43:00.01 spid15s          owner id=process81607588
2011-02-09 15:43:00.01 spid15s         waiter-list
2011-02-09 15:43:00.01 spid15s          waiter id=process81607c18
2011-02-09 15:43:00.01 spid15s          waiter id=process81607978
2011-02-09 15:43:00.01 spid15s          waiter id=process816076d8
2011-02-09 15:43:00.01 spid15s          waiter id=process81607198
2011-02-09 15:43:00.01 spid15s          waiter id=process81607048
2011-02-09 15:43:00.01 spid15s          waiter id=process816069b8
2011-02-09 15:43:00.01 spid15s          waiter id=process81606868
2011-02-09 15:43:00.01 spid15s          waiter id=process81606478
2011-02-09 15:43:00.01 spid15s          waiter id=process81606328
2011-02-09 15:43:00.01 spid15s          waiter id=process816061d8
2011-02-09 15:43:00.01 spid15s          waiter id=process81606088
2011-02-09 15:43:00.01 spid15s          waiter id=processbafeb8
2011-02-09 15:43:00.01 spid15s          waiter id=processbafac8
2011-02-09 15:43:00.01 spid15s          waiter id=processbaf978
2011-02-09 15:43:00.01 spid15s          waiter id=processbaf438
2011-02-09 15:43:00.01 spid15s          waiter id=processbaf198

Finally, I have a link to the xdl generated by Profiler if you want to explore it from the comfortable confines of SSMS.

Update 2011-02-10 15:00:00.000

My understanding of what was causing the deadlock contention is incorrect. The deadlock graph had more to show. Followup post tomorrowish

3 comments:

Dave, Sydney said...

Hey there World of Whatever,

I found your very helpful web page because I am a data architect about to do exactly what you are doing - extracting the Pershing Standard Files into SQL Server. I was interested to see your comment about the files changing every quarter - it's something I noticed also when reading all the documentation.

Due to Change Management requirements it's not feasible to be changing an SSIS package every few months, so we are contemplating a meta-data table, well, two actually. One to hold the subset of standard files we want to transform, and another to map the data points we require with their matching file and ordinal position. if we treat each row in the second metatable as slowly changing data with a start and end date we can enter new file changes in advance with the correct start date. So monitoring the quarterly newsletters and keeping meta-data tables up to date will hopefully mean we can have an SSIS package that doesn't have to change over time.

It's a maintenance overhead though, which I don't really like. Much prefer to have Pershing push the results of their reports in csv format, like SSRS, because they are a nice flat table format, but that doesn't appear to be an option they provide :-(

Interested to see your SQL table structure - exactly what I had in mind.

If you have any other advice/tips/traps for young players that you can share I'd be very appreciative. And thanks for your great blog post.

Regards,

Dave

Carrie said...

Hello World of Whatever,

I was hoping you can help me. I'm the Compliance, Financial, IT (Yeah right)... everything for a small financial services firm. We use Pershing, Quickbooks and your standard MS Office Package for everything. I was put in charge of translating these things into a usable format. I have an accounting degree and would consider myself an intermediate to advanced user in Excel (very basic VBA); hardly a data technician or computer guru. Before I go into everything I've tried, can you tell me, is it possible to create a template to translate these files in Excel or Access?
Any help you could give me would be GREATLY appreciated. I've been passively working on this since 2013 and everything leads to a dead end!

Thanks,
Carrie

Bill Fellows said...

Hi Carrie, on vacation for the next two weeks. Send me a reminder email June 16th and we can chat. Bill.fellows at gmail.com