July 7, 2008 at 1:53 am
Hi. I'm wondering if anyone can help me figure out what is happening here. I'm slightly beyond SQL newbie, but I'm no dba.
I'm calling a number of SSIS packages from vbscript. Being vbscript, I have to use a loop to wait for the package to complete before continuing.
I have six packages. Four only do internal SQL stuff; two import data from text files. The four complete properly, but when I call the two that import from text files, they can't be returning a completed status. Vbscript keeps looping up until the timeout, and only then reports the package as successfully completed.
When I run the packages directly in SQL or from visual studio they run in a matter of seconds and appear to complete normally.
When I look in the log I can see the delay occuring during the "final commit for insertion", whatever that it. There is always a gap here as long as my timeout in vbscript. So if I set my timeout to 2 minutes there is a 2 minute delay at this point, if it's 1 minute there is a 1 minute delay etc.
Info: 2008-07-07 01:00:01.65
Code: 0x402090DF
Source: Data Flow Task OLE DB Destination [181]
Description: The final commit for the data insertion has started.
End Info
Info: 2008-07-07 01:01:01.36
Code: 0x402090E0
Source: Data Flow Task OLE DB Destination [181]
Description: The final commit for the data insertion has ended.
End Info
Can anyone tell me what is going on or give me some tips on where to look? The vbscript code is as follows.
'-----------------------------------------------------
' Function RunSSIS
' + Call a SQL SSIS package
' + Returns 0 for success
'----------------------------------------------------
Function RunSSIS(packageName)
Dim strCmd, strOutput
Dim objShell, objExec
Dim iCount
Const SSIS_SUCCESS = "The package execution returned DTSER_SUCCESS"
WriteLog "Running SSIS package " & packageName
strCmd = "dtexec /DTS ""\MSDB\" & packageName & """ /SERVER servername /MAXCONCURRENT "" -1 "" /CHECKPOINTING OFF /REPORTING V"
Set objShell = CreateObject("WScript.Shell")
Set objExec = objShell.Exec(strCmd)
iCount = 0
Do Until objExec.Status Or (iCount > 60)
Wscript.sleep 1000 'pause 1 second
iCount = iCount + 1
Loop
strOutput = objExec.stdOut.ReadAll
If InStr(strOutput, SSIS_SUCCESS) > 0 Then
RunSSIS = 0
WriteLog "Package completed successfully."
Else
RunSSIS = 1
WriteLog "Package failed. See " & SSISLogFileName & " for the full output."
End If
objSSISLogFile.Write(strOutput)
End Function
Thanks,
Carol
July 7, 2008 at 6:38 am
The "Final Commit" it is referring to is the actual commit of the data in the table. So, you probably have an OLEDB Destination component doing your insert. I would guess you are using the "Fast Load" option which is actually doing a bulk-insert. There are some options for table lock, make sure you are not locking the table if other processes use it at the same time.
I would guess you have a resource lock problem. Run your program and while it is hung up, run the procedure sp_who2 on your SQL Server that the data is being imported into. You will probably find that the BlkBy column has something in it blocking your process. You can run DBCC INPUTBUFFER() on the process id to figure out exactly what the process is doing.
It could be that one of your packages is continuing to hold a lock while another is running or that you have a parallel process within the package causing the issue. Sometimes these do not come up when running through Visual Studio because of the way the IDE threads differently than the runtime assembly.
July 7, 2008 at 8:15 am
Hi Michael - thanks for your reponse. If I could trouble you a bit more...
There is nothing in the BlkBy column.
However I am confused by what I am seeing between running sp_who2 and Activity Monitor because a different process is listed as RUNNABLE in each (and yes I am on the same server and I am refreshing).
AND they are still listed as RUNNABLE long after my package has finished. Is the process list somehow not being updated despite my re-executes and refreshes?
In sp_who2 this one is runnable-
73 RUNNABLE domain\usernameservername . RegistrationSELECT INTO 445417507/07 15:58:49Microsoft SQL Server Management Studio - Query73 0
In Activity Monitor it's this one-
75 create table #tmpDBCCinputbuffer ([Event Type] nvarchar(512), [Parameters] int, [Event Info] nvarchar(512))
insert into #tmpDBCCinputbuffer exec ('DBCC INPUTBUFFER(75)')
select [Event Info] from #tmpDBCCinputbuffer
This is on a dev server with no-one else using it and no other activity - though I'm seeing exactly the same behaviour on the production server as well.
Also changing from "table or view - fast load" to "table or view" hasn't made any difference. Otherwise I'm just using default settings in the data flow task of the SSIS package, to get the data imported from the text file into a table.
Thanks again,
Carol
July 7, 2008 at 8:35 am
I'll re-read this in a minute in more detail to try to help a bit more, but right away I can tell you that the RUNNABLE process you are seeing when you run sp_who2 is not the bulk insert - it is a SELECT INTO process and probably the spid that is actually running sp_who2 (look in the lower right corner of Management Studio).
You are probably looking at the wrong process.
July 7, 2008 at 12:00 pm
Ok, so I went back and looked through your original post in some more detail also.
So if I am reading this correctly, when you run the package using the shell object in your VBScript, the shell object is not returning a true status when the packages with a file source in the data flow complete - even though the package has apparently completed successfully.
I assume you have run these from the command line manually and the package does return a success message when it completes. If you have not, you should make sure it does. Is there anything else different about these particular packages? Make sure you look carefully. As a test, try adding something else after the data flow in the control flow of the packages - like a T-SQl command that does not do much (SELECT GETDATE() or something) to see if it has something to do with the reporting back of status from your data flow to the command line.
It may be that when the package runs it is completing successfully and not reporting back correctly. SSIS has had some problems with this and the visual studio GUI, so you may be experiencing the same type of issue - sometimes boxes never turn green. What service pack of SSIS are you on?
July 8, 2008 at 6:04 am
Hi Michael. Thanks again for your help - it is much appreciated!
When I use dtexec, with exactly the same argument, to run the SSIS from the command prompt it completes properly.
I added another SQL task after the Data Flow task - it hasn't made any difference.
Here's the output when I run from the command line-
Microsoft (R) SQL Server Execute Package Utility
Version 9.00.3042.00 for 32-bit
Copyright (C) Microsoft Corp 1984-2005. All rights reserved.
Started: 12:53:22 PM
Info: 2008-07-08 12:53:23.26
Code: 0x4004300A
Source: Import text file DTS.Pipeline
Description: Validation phase is beginning.
End Info
Progress: 2008-07-08 12:53:23.28
Source: Import text file
Validating: 0% complete
End Progress
Progress: 2008-07-08 12:53:23.28
Source: Import text file
Validating: 50% complete
End Progress
Progress: 2008-07-08 12:53:23.37
Source: Import text file
Validating: 100% complete
End Progress
Progress: 2008-07-08 12:53:23.56
Source: Clear TIES_Users_Import
Executing query "truncate table TIES_Users_Import
".: 100% complete
End Progress
Info: 2008-07-08 12:53:23.56
Code: 0x4004300A
Source: Import text file DTS.Pipeline
Description: Validation phase is beginning.
End Info
Progress: 2008-07-08 12:53:23.57
Source: Import text file
Validating: 0% complete
End Progress
Progress: 2008-07-08 12:53:23.57
Source: Import text file
Validating: 50% complete
End Progress
Progress: 2008-07-08 12:53:23.57
Source: Import text file
Validating: 100% complete
End Progress
Info: 2008-07-08 12:53:23.59
Code: 0x40043006
Source: Import text file DTS.Pipeline
Description: Prepare for Execute phase is beginning.
End Info
Progress: 2008-07-08 12:53:23.59
Source: Import text file
Prepare for Execute: 0% complete
End Progress
Progress: 2008-07-08 12:53:23.59
Source: Import text file
Prepare for Execute: 50% complete
End Progress
Progress: 2008-07-08 12:53:23.59
Source: Import text file
Prepare for Execute: 100% complete
End Progress
Info: 2008-07-08 12:53:23.60
Code: 0x40043007
Source: Import text file DTS.Pipeline
Description: Pre-Execute phase is beginning.
End Info
Progress: 2008-07-08 12:53:23.60
Source: Import text file
Pre-Execute: 0% complete
End Progress
Info: 2008-07-08 12:53:23.62
Code: 0x402090DC
Source: Import text file Flat File Source [1]
Description: The processing of file "C:\Program Files\Microsoft Identity Inte
gration Server\MaData\TIES_Users\TiesUsers.txt" has started.
End Info
Progress: 2008-07-08 12:53:23.62
Source: Import text file
Pre-Execute: 50% complete
End Progress
Progress: 2008-07-08 12:53:23.63
Source: Import text file
Pre-Execute: 100% complete
End Progress
Info: 2008-07-08 12:53:23.63
Code: 0x4004300C
Source: Import text file DTS.Pipeline
Description: Execute phase is beginning.
End Info
DataFlow: 2008-07-08 12:53:23.88
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
Info: 2008-07-08 12:53:24.82
Code: 0x402090DE
Source: Import text file Flat File Source [1]
Description: The total number of data rows processed for file "C:\Program Fil
es\Microsoft Identity Integration Server\MaData\TIES_Users\TiesUsers.txt" is 306
75.
End Info
DataFlow: 2008-07-08 12:53:31.07
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 12:53:37.76
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 12:53:43.96
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 12:53:50.40
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 12:53:56.67
Source: Import text file
Component "OLE DB Destination" (181) will receive 2059 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 12:53:58.98
Source: Import text file
Component "OLE DB Destination" (181) was given end of rowset on input "OLE DB
Destination Input" (194)
End DataFlow
Info: 2008-07-08 12:53:58.99
Code: 0x40043008
Source: Import text file DTS.Pipeline
Description: Post Execute phase is beginning.
End Info
Progress: 2008-07-08 12:53:58.99
Source: Import text file
Post Execute: 0% complete
End Progress
Info: 2008-07-08 12:53:58.99
Code: 0x402090DD
Source: Import text file Flat File Source [1]
Description: The processing of file "C:\Program Files\Microsoft Identity Inte
gration Server\MaData\TIES_Users\TiesUsers.txt" has ended.
End Info
Progress: 2008-07-08 12:53:58.99
Source: Import text file
Post Execute: 50% complete
End Progress
Progress: 2008-07-08 12:53:58.99
Source: Import text file
Post Execute: 100% complete
End Progress
Info: 2008-07-08 12:53:59.01
Code: 0x40043009
Source: Import text file DTS.Pipeline
Description: Cleanup phase is beginning.
End Info
Progress: 2008-07-08 12:53:59.01
Source: Import text file
Cleanup: 0% complete
End Progress
Progress: 2008-07-08 12:53:59.01
Source: Import text file
Cleanup: 50% complete
End Progress
Progress: 2008-07-08 12:53:59.01
Source: Import text file
Cleanup: 100% complete
End Progress
Info: 2008-07-08 12:53:59.01
Code: 0x4004300B
Source: Import text file DTS.Pipeline
Description: "component "OLE DB Destination" (181)" wrote 30674 rows.
End Info
Progress: 2008-07-08 12:54:01.76
Source: Update TIES_Users
Executing query "INSERT INTO TIES_Users
SELECT i.*, 'imported', NUL".: 100% complete
End Progress
DTExec: The package execution returned DTSER_SUCCESS (0).
Started: 12:53:22 PM
Finished: 12:54:01 PM
Elapsed: 38.969 seconds
And here's the output when I run the same dtexec command line from a vbscript (with a 120 sec timeout on the loop). The delay is being reported at a different place now - perhaps because of the extra SQL Task I added?
Microsoft (R) Windows Script Host Version 5.6
Copyright (C) Microsoft Corporation 1996-2001. All rights reserved.
Microsoft (R) SQL Server Execute Package Utility
Version 9.00.3042.00 for 32-bit
Copyright (C) Microsoft Corp 1984-2005. All rights reserved.
Started: 1:25:26 PM
Info: 2008-07-08 13:25:26.66
Code: 0x4004300A
Source: Import text file DTS.Pipeline
Description: Validation phase is beginning.
End Info
Progress: 2008-07-08 13:25:26.66
Source: Import text file
Validating: 0% complete
End Progress
Progress: 2008-07-08 13:25:26.66
Source: Import text file
Validating: 50% complete
End Progress
Progress: 2008-07-08 13:25:26.74
Source: Import text file
Validating: 100% complete
End Progress
Progress: 2008-07-08 13:25:26.93
Source: Clear TIES_Users_Import
Executing query "truncate table TIES_Users_Import
".: 100% complete
End Progress
Info: 2008-07-08 13:25:26.93
Code: 0x4004300A
Source: Import text file DTS.Pipeline
Description: Validation phase is beginning.
End Info
Progress: 2008-07-08 13:25:26.93
Source: Import text file
Validating: 0% complete
End Progress
Progress: 2008-07-08 13:25:26.93
Source: Import text file
Validating: 50% complete
End Progress
Progress: 2008-07-08 13:25:26.95
Source: Import text file
Validating: 100% complete
End Progress
Info: 2008-07-08 13:25:26.95
Code: 0x40043006
Source: Import text file DTS.Pipeline
Description: Prepare for Execute phase is beginning.
End Info
Progress: 2008-07-08 13:25:26.95
Source: Import text file
Prepare for Execute: 0% complete
End Progress
Progress: 2008-07-08 13:25:26.95
Source: Import text file
Prepare for Execute: 50% complete
End Progress
Progress: 2008-07-08 13:25:26.95
Source: Import text file
Prepare for Execute: 100% complete
End Progress
Info: 2008-07-08 13:25:26.96
Code: 0x40043007
Source: Import text file DTS.Pipeline
Description: Pre-Execute phase is beginning.
End Info
Progress: 2008-07-08 13:25:26.96
Source: Import text file
Pre-Execute: 0% complete
End Progress
Info: 2008-07-08 13:25:26.96
Code: 0x402090DC
Source: Import text file Flat File Source [1]
Description: The processing of file "C:\Program Files\Microsoft Identity Inte
gration Server\MaData\TIES_Users\TiesUsers.txt" has started.
End Info
Progress: 2008-07-08 13:25:26.96
Source: Import text file
Pre-Execute: 50% complete
End Progress
Progress: 2008-07-08 13:25:26.98
Source: Import text file
Pre-Execute: 100% complete
End Progress
Info: 2008-07-08 13:25:26.98
Code: 0x4004300C
Source: Import text file DTS.Pipeline
Description: Execute phase is beginning.
End Info
DataFlow: 2008-07-08 13:25:27.09
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
Info: 2008-07-08 13:25:27.37
Code: 0x402090DE
Source: Import text file Flat File Source [1]
Description: The total number of data rows processed for file "C:\Program Fil
es\Microsoft Identity Integration Server\MaData\TIES_Users\TiesUsers.txt" is 306
75.
End Info
DataFlow: 2008-07-08 13:25:33.81
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 13:25:41.52
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 13:25:48.27
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 13:25:54.99
Source: Import text file
Component "OLE DB Destination" (181) will receive 5723 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 13:26:01.73
Source: Import text file
Component "OLE DB Destination" (181) will receive 2059 rows on input "OLE DB
Destination Input" (194)
End DataFlow
DataFlow: 2008-07-08 13:26:03.82
Source: Import text file
Component "OLE DB Destination" (181) was given end of rowset on input "OLE DB
Destination Input" (194)
End DataFlow
Info: 2008-07-08 13:27:27.21
Code: 0x40043008
Source: Import text file DTS.Pipeline
Description: Post Execute phase is beginning.
End Info
Progress: 2008-07-08 13:27:27.21
Source: Import text file
Post Execute: 0% complete
End Progress
Info: 2008-07-08 13:27:27.21
Code: 0x402090DD
Source: Import text file Flat File Source [1]
Description: The processing of file "C:\Program Files\Microsoft Identity Inte
gration Server\MaData\TIES_Users\TiesUsers.txt" has ended.
End Info
Progress: 2008-07-08 13:27:27.21
Source: Import text file
Post Execute: 50% complete
End Progress
Progress: 2008-07-08 13:27:27.21
Source: Import text file
Post Execute: 100% complete
End Progress
Info: 2008-07-08 13:27:27.21
Code: 0x40043009
Source: Import text file DTS.Pipeline
Description: Cleanup phase is beginning.
End Info
Progress: 2008-07-08 13:27:27.21
Source: Import text file
Cleanup: 0% complete
End Progress
Progress: 2008-07-08 13:27:27.21
Source: Import text file
Cleanup: 50% complete
End Progress
Progress: 2008-07-08 13:27:27.21
Source: Import text file
Cleanup: 100% complete
End Progress
Info: 2008-07-08 13:27:27.21
Code: 0x4004300B
Source: Import text file DTS.Pipeline
Description: "component "OLE DB Destination" (181)" wrote 30674 rows.
End Info
Progress: 2008-07-08 13:27:30.01
Source: Update TIES_Users
Executing query "INSERT INTO TIES_Users
SELECT i.*, 'imported', NUL".: 100% complete
End Progress
DTExec: The package execution returned DTSER_SUCCESS (0).
Started: 1:25:26 PM
Finished: 1:27:30 PM
Elapsed: 123.782 seconds
Like I said before, I run several other SSIS packages using exactly the same vbscript and I don't see any delay with them. The two scripts that have a delay both contain a Data Flow task which imports data from a text file.
I'm also seeing exactly the same behaviour when I run the dtsx file directly from the file system. :crazy:
July 8, 2008 at 6:16 am
I'm low on ideas here.
I would try to copy the data into Excel and switch the connection manager out. Possibly try an ODBC driver for text files or the MULTIFLATFILE connector. Try to confirm that it is really the use of the text file connection manager that you are using.
If it turnes out to be, you may need to conect MS.
July 9, 2008 at 7:32 am
I have stumbled on a workaround.
The SSIS is not returning a status to vbscript when an Import tasks is involved, however it is keeping the objExec.stdOut locked until the package finishes.
So all I need to do is use objExec.stdOut directly after running the package. The script then waits for it to be available.
If I don't use objExec.stdOut the vbscript continues immediately on its merry way without waiting for the SSIS to finish.
Actually in the original script I posted I was using objExec.stdOut.ReadAll, but I still had the wait loop, because normally you need it when using the vbscript Exec function.
The following script excerpt is working for all my SSIS packages-
strCmd = "dtexec /DTS ""\MSDB\" & packageName & """ /SERVER servername /MAXCONCURRENT "" -1 "" /CHECKPOINTING OFF /REPORTING V"
Set objShell = CreateObject("WScript.Shell")
Set objExec = objShell.Exec(strCmd)
strOutput = objExec.stdOut.ReadAll
I could also just have
wscript.echo objExec.stdOut.ReadAll
Incidentally, we did open a call with MS about this as I do think there's something odd going on with that status - if they get back to me with anything interesting I'll update this thread.
Carol
Viewing 8 posts - 1 through 7 (of 7 total)
You must be logged in to reply to this topic. Login to reply