October 6, 2009 at 12:50 pm
We have a few processes going on here which are automated and which run after hours. At our company, 6:00 pm is safe, because all employees are gone by then.
So around 6:15, we have one procedure which establishes two connections: one to a SQL Server db, and another to a Progress one.
It does a lot of select statements, then loops through and does some updates.
We log the progress in a little text file.
Every day for several days now, it's been failing. I have snipped huge chunks away from the logs and left samples to see what is going on. It's not that daunting.
*************************Starting... 9/18/2009 6:15 PM*************************
Started with command line: ChempaxLive admin admin c:\s2pship Log.txt
RiccaDB connection string: Data Source= (snip)
Chempax connection string: DSN=(snip)
Attemping to open RiccaDB connection...
RiccaDB connection successfully opened
Attempting to ExecuteReader with sqlcommand: 'SELECT * FROM ship_upsxptsum' on database: ricca
Successfull ExecuteReader with sqlcommand: 'SELECT * FROM ship_upsxptsum' on database: ricca
Attemping to open ChempaxDB connection...
ChempaxDB connection successfully opened
Attempting to ExecuteNonQuery with sqlcommand: 'LOCK TABLE PUB."ORDER-SHIPMENT-HDR" IN SHARE MODE' on database:
Successfull ExecuteNonQuery with sqlcommand: 'LOCK TABLE PUB."ORDER-SHIPMENT-HDR" IN SHARE MODE' on database:
Attempting to ExecuteScalar with sqlcommand: 'SELECT MIN("ship-tran-num") AS tranNum FROM PUB."ORDER-SHIPMENT-HDR" WHERE not cancelled = 1 and "order-num" = '333648' and "tracking-num" = '' GROUP BY "order-num" ' on database:
Successfull ExecuteScalar with sqlcommand: 'SELECT MIN("ship-tran-num") AS tranNum FROM PUB."ORDER-SHIPMENT-HDR" WHERE not cancelled = 1 and "order-num" = '333648' and "tracking-num" = '' GROUP BY "order-num" ' on database:
(snip a few hundred select statements)
Attempting to ExecuteNonQuery with sqlcommand: 'UPDATE PUB."ORDER-SHIPMENT-HDR" SET "Total-Packages" = 1, "Haz-Mat-Handling-Charge" = 0, "Freight-Cost" = 10.2592, "Freight-Rate" = 10.2592, "Tracking-Num" = '1Z4366350348404907' WHERE "Freight-Cost" = 0 AND "Tracking-num" = '' AND NOT Cancelled = 1 AND "ship-tran-num" = 420110 AND "order-num" = 387460 ' on database:
Successfull ExecuteNonQuery with sqlcommand: 'UPDATE PUB."ORDER-SHIPMENT-HDR" SET "Total-Packages" = 1, "Haz-Mat-Handling-Charge" = 0, "Freight-Cost" = 10.2592, "Freight-Rate" = 10.2592, "Tracking-Num" = '1Z4366350348404907' WHERE "Freight-Cost" = 0 AND "Tracking-num" = '' AND NOT Cancelled = 1 AND "ship-tran-num" = 420110 AND "order-num" = 387460 ' on database:
Attemping to open second RiccaDB connection...
Second RiccaDB connection successfully opened
Attemping to open a transaction on second RiccaDB connection...
Successfully opened a transaction on second RiccaDB connection
Attempting to ExecuteNonQuery with sqlcommand: 'UPDATE ship_upsxpt SET processed_flag = 'Y' WHERE order_num = '387460'' on database: ricca
Successfull ExecuteNonQuery with sqlcommand: 'UPDATE ship_upsxpt SET processed_flag = 'Y' WHERE order_num = '387460'' on database: ricca
Attemping to commit the open transaction on second RiccaDB connection...
Successfully committed the open transaction on second RiccaDB connection
Attemping to close the second RiccaDB connection...
Successfully closed the second RiccaDB connection...
(snip)
Attempting to ExecuteNonQuery with sqlcommand: 'UPDATE PUB."ORDER-SHIPMENT-HDR" SET "Total-Packages" = 1, "Haz-Mat-Handling-Charge" = 0, "Freight-Cost" = 10.3152, "Freight-Rate" = 10.3152, "Tracking-Num" = '1Z7579360363085157' WHERE "Freight-Cost" = 0 AND "Tracking-num" = '' AND NOT Cancelled = 1 AND "ship-tran-num" = 447729 AND "order-num" = 406419 ' on database:
Successfull ExecuteNonQuery with sqlcommand: 'UPDATE PUB."ORDER-SHIPMENT-HDR" SET "Total-Packages" = 1, "Haz-Mat-Handling-Charge" = 0, "Freight-Cost" = 10.3152, "Freight-Rate" = 10.3152, "Tracking-Num" = '1Z7579360363085157' WHERE "Freight-Cost" = 0 AND "Tracking-num" = '' AND NOT Cancelled = 1 AND "ship-tran-num" = 447729 AND "order-num" = 406419 ' on database:
Attemping to open second RiccaDB connection...
Second RiccaDB connection successfully opened
Attemping to open a transaction on second RiccaDB connection...
Successfully opened a transaction on second RiccaDB connection
Attempting to ExecuteNonQuery with sqlcommand: 'UPDATE ship_upsxpt SET processed_flag = 'Y' WHERE order_num = '406419'' on database: ricca
s2pShip Failed:
Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
The statement has been terminated.
*************************Failure... 9/18/2009 8:30 PM*************************
I should note that I ran that update statement myself manually in SSMS, and it worked fine. I should also note that I already thought of the possibility that we have some other process which is going on at 6:15 which bogs down the servers, and don't think that's it. One reason is because I manually ran this process at 10:30 yesterday with the same results. In all cases, it runs all the select and update statements, then fails with the very first update which sets the proceesed_flag field to Y. Every time, this is the part that fails, on the very first one (it should loop through and there should be many more)
Not sure what to look for to find out why it fails at any time of day on this same type of query.
October 6, 2009 at 12:57 pm
Just off top of my head has the field 'processed_flag' field or the table that field is in had any changes to it?
If you run profiler, then execute your procedure does it give any additional information for you?
Shawn Melton
Twitter: @wsmelton
Blog: wsmelton.github.com
Github: wsmelton
October 6, 2009 at 12:59 pm
I will check on recent changes.
Not sure what profiler is. Got a link to a tutorial?
October 6, 2009 at 1:05 pm
Sorry, SQL Server Profiler, it is a tool installed when you install SSMS (Management Studio) for SQL Server 2005. The end section of this link shows basic use of Profiler.
Shawn Melton
Twitter: @wsmelton
Blog: wsmelton.github.com
Github: wsmelton
October 6, 2009 at 2:11 pm
Is there a Timout/Connection Timout property you can set for the Progress DB connection?
October 6, 2009 at 2:13 pm
I am not sure, but I don't think it will matter, because this thing is failing on the SQL server connection.
October 6, 2009 at 2:16 pm
middletree (10/6/2009)
I am not sure, but I don't think it will matter, because this thing is failing on the SQL server connection.
How are you connecting to the SQL Server then? Or did I misunderstand and it's local on the SQL machine?
October 6, 2009 at 2:17 pm
The connection string is at the top of my code. I snipped most of it because I didn't want to post certain parts of it on a public website.
October 6, 2009 at 2:38 pm
Can your conn string be anonymized and posted?
If not, I would recommend what Melton said above and start a Profiler trace to see the duration of the query that fails. Here's how you can get started:
Open SQL Server Profiler, Create a new trace (File --> New Trace). Log in to the server on which the database in question resides. You will need to have sa access to the SQL instance you wish to monitor.
Leave the first tab at its defaults (the Standard template), and in the Events Selection tab, make sure RPC:Completed, SQL:BatchStarted, SQL:BatchCompleted, and Duration are checked. In the lower right-hand quadrant, check the "Show All Columns" check box, and scroll right to make sure the DatabaseName column is checked. You'll also want to ensure that other columns like LoginName, TextData, HostName, and ApplicationName are selected for all events you're capturing.
Finally, click the "Column Filters" button, click on "DatabaseName" in the List Box, and expand the "Like" container. Include the database name you want to monitor, then click OK, then Run. I always log in through SSMS and run a simple query against that specific database to make sure my query comes through in the trace and that I have the columns I want to look at.
If the duration of your failed queries is always 1000 ms or a certain duration you can bet it's a TimeOut property set to govern the length of the .NET/ODBC/OLEDB/whatever connection.
MJM
October 6, 2009 at 2:41 pm
Sure, I only trimmed the connection stuff because I didn't think it was important.
The 2nd one is the Progress one.
RiccaDB connection string: Data Source=xxxx;Initial Catalog=ricca;Integrated Security=True
Chempax connection string: DSN=ChempaxLive;UID=xxxx;PWD=xxxx
October 6, 2009 at 3:02 pm
middletree (10/6/2009)
RiccaDB connection string: Data Source=xxxx;Initial Catalog=ricca;Integrated Security=TrueChempax connection string: DSN=ChempaxLive;UID=xxxx;PWD=xxxx
Can you try to run the following using ONLY the SQL connection? This will at least make sure you can hold a connection open for 90 seconds, followed by a SELECT GETDATE() without error.
WAITFOR DELAY '00:01:30.000'
SELECT GETDATE()
October 6, 2009 at 3:26 pm
It ran without error. The result set, of course, is:
2009-10-06 16:21:13.143
October 6, 2009 at 3:27 pm
I've not seen that delay code before. Tempting to try it for 5 minutes or something.
thanks
Viewing 13 posts - 1 through 12 (of 12 total)
You must be logged in to reply to this topic. Login to reply