Time between scripts in a batch increased after upgrade

isulpova · Post by **isulpova** » Tue Feb 21, 2012 6:32 pm

After upgrading a server from V880 Solaris 8/8 CPU/32G RAM to E2900 Solaris 10/12 CPU/24 Cores 80G RAM the speed of execution of some scripts has visibly slowed. The problem seems to be in a slight increase in the time between running the scripts - from 2-5 sec to 20-60 sec. This adds up to multiple hours over the course of the executing the entire suit of scripts.

What exactly happens during those "in-between" moments. What could be responsible for the time increase? What are fixes can be suggested?

Example:

This is the log of a script ran prior to the upgrade:

Code: Select all

2:55:37 AM	11/18/2011	Control		Starting Job EmployeesData. (...)
2:55:37 AM	11/18/2011	Info		Environment variable settings: (...)	
2:55:41 AM	11/18/2011	RunJob		EmployeesData-> (SADetailsExtract): Job run requested(...)
2:55:41 AM	11/18/2011	Info		EmployeesData..JobControl (DSRunJob): Wainting for job SADetailsExtract to start
2:55:42 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SADetailsExtract to finish
2:55:45 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Job SADetailsExtract finished, status = 1 (Finished OK)
2:55:46 AM	11/18/2011	RunJob		EmployeeData-> (SAPostCodeExtract): Job run requested(...)
2:55:46 AM	11/18/2011	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAPostCodeExtract to start
2:55:48 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAPostCodeExtract to finish
2:55:49 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Job SAPostCodeExtract finished, status = 1 (Finished OK)
2:55:50 AM	11/18/2011	RunJob		EmployeeData-> (SADetailswithContract): Job run requested(...)
2:55:50 AM	11/18/2011	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SADetailswithContract to start
2:55:51 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SADetailswithContract to finish
2:55:53 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Job SADetailswithContract finished, status = 1 (Finished OK)
2:55:58 AM	11/18/2011	RunJob		EmployeeData-> (SAHashFilesFromSP): Job run requested(...)
2:55:58 AM	11/18/2011	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAHashFilesFromSP to start
2:56:00 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAHashFilesFromSP to finish
2:56:01 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Job SAHashFilesFromSP finished, status = 1 (Finished OK)
2:56:04 AM	11/18/2011	RunJob		EmployeeData-> (HomeLocationHashFileFromSP): Job run requested(...)
2:56:04 AM	11/18/2011	Info		EmployeeData..JobControl (DSRunJob): Wainting for job HomeLocationHashFileFromSP to start
2:56:05 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job HomeLocationHashFileFromSP to finish
2:56:07 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Job HomeLocationHashFileFromSP finished, status = 1 (Finished OK)
2:56:08 AM	11/18/2011	RunJob		EmployeeData-> (SAInsertToSP): Job run requested(...)
2:56:08 AM	11/18/2011	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAInsertToSP to start
2:56:09 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAInsertToSP to finish
2:56:11 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Job SAInsertToSP finished, status = 1 (Finished OK)
2:56:12 AM	11/18/2011	RunJob		EmployeeData-> (SAUpdateInacEmployee): Job run requested(...)
2:56:12 AM	11/18/2011	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAUpdateInacEmployee to start
2:56:14 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAUpdateInacEmployee to finish
2:56:15 AM	11/18/2011	Info		EmployeesData..JobControl (DSWaitForJob): Job SAUpdateInacEmployee finished, status = 1 (Finished OK)
2:56:15 AM	11/18/2011	Control		FinishedJOb EmployeesData

This is the log of the same script ran after the upgrade:

Code: Select all

2:49:09 AM	02/18/2012	Control		Starting Job EmployeesData. (...)
2:49:09 AM	02/18/2012	Info		Environment variable settings: (...)	
2:49:56 AM	02/18/2012	RunJob		EmployeesData-> (SADetailsExtract): Job run requested(...)
2:49:56 AM	02/18/2012	Info		EmployeesData..JobControl (DSRunJob): Wainting for job SADetailsExtract to start
2:49:57 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SADetailsExtract to finish
2:49:59 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Job SADetailsExtract finished, status = 1 (Finished OK)
2:50:22 AM	02/18/2012	RunJob		EmployeeData-> (SAPostCodeExtract): Job run requested(...)
2:50:22 AM	02/18/2012	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAPostCodeExtract to start
2:50:23 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAPostCodeExtract to finish
2:50:25 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Job SAPostCodeExtract finished, status = 1 (Finished OK)
2:50:57 AM	02/18/2012	RunJob		EmployeeData-> (SADetailswithContract): Job run requested(...)
2:50:57 AM	02/18/2012	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SADetailswithContract to start
2:50:58 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SADetailswithContract to finish
2:51:00 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Job SADetailswithContract finished, status = 1 (Finished OK)
2:52:58 AM	02/18/2012	RunJob		EmployeeData-> (SAHashFilesFromSP): Job run requested(...)
2:52:58 AM	02/18/2012	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAHashFilesFromSP to start
2:52:59 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAHashFilesFromSP to finish
2:53:01 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Job SAHashFilesFromSP finished, status = 1 (Finished OK)
2:54:07 AM	02/18/2012	RunJob		EmployeeData-> (HomeLocationHashFileFromSP): Job run requested(...)
2:54:07 AM	02/18/2012	Info		EmployeeData..JobControl (DSRunJob): Wainting for job HomeLocationHashFileFromSP to start
2:54:08 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job HomeLocationHashFileFromSP to finish
2:54:10 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Job HomeLocationHashFileFromSP finished, status = 1 (Finished OK)
2:54:53 AM	02/18/2012	RunJob		EmployeeData-> (SAInsertToSP): Job run requested(...)
2:54:53 AM	02/18/2012	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAInsertToSP to start
2:54:54 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAInsertToSP to finish
2:54:56 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Job SAInsertToSP finished, status = 1 (Finished OK)
2:55:29 AM	02/18/2012	RunJob		EmployeeData-> (SAUpdateInacEmployee): Job run requested(...)
2:55:29 AM	02/18/2012	Info		EmployeeData..JobControl (DSRunJob): Wainting for job SAUpdateInacEmployee to start
2:55:30 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Waiting for job SAUpdateInacEmployee to finish
2:55:32 AM	02/18/2012	Info		EmployeesData..JobControl (DSWaitForJob): Job SAUpdateInacEmployee finished, status = 1 (Finished OK)
2:55:32 AM	02/18/2012	Control		Finished job EmployeesData

As can be seen in an example of the first script on the list, the SADetailsExtract actual time to run the script (between lines "Waiting for job to start" and "Job finished, status =1") is 3 sec in both cases. The time betwenn SADetailsExtract and next script SAPostCodeExtract (between lines "Job finished" and "Job run requested") is about 1 sec pre-upgarde and 23 sec post-upgrade.

qt_ky · Post by **qt_ky** » Tue Feb 21, 2012 6:41 pm

Are the hardware upgrades in place on the same server or has it also involved installing the software on a separate server then a migration?

I would start by checking &PH& in the DataStage project. First DataStage Administrator command: COUNT &PH&

Next: CLEAR.FILE &PH&

Here's one post about it.

viewtopic.php?t=83705&highlight=CLEAR.FILE+%26PH%26

You can find some tech notes on the IBM Support Portal as well.

I would also check auto-purge settings on specific job logs and at the project level. Make sure your job logs are not growing too large.

You might want to check the type of logging being done too.

Kryt0n · Post by **Kryt0n** » Tue Feb 21, 2012 6:54 pm

Sorry, not going to be much help but have to laugh at how everyone thought this machine was going to stonk the processing and come in the next morning to find it took longer... (although would be interested to know the kind of row output it generates for computational intensive and straight pass through)

What kind of migration occurred? A shift of existing jobs/executables or only jobs and re-compiled?
Is the XMETA on the same machine, or at least as close as it was before the migration?
Do scripts/processes/applications outside of datastage run as per pre-migration or noticeable changes elsewhere?

qt_ky · Post by **qt_ky** » Tue Feb 21, 2012 7:01 pm

The post says version 7.x... not so sure it's going to have XMETA.

For different servers there can easily be OS and DataStage setting differences.

chulett · Post by **chulett** » Tue Feb 21, 2012 7:13 pm

Yah, no XMETA anything pre-8.

kandyshandy · Post by **kandyshandy** » Tue Feb 21, 2012 8:52 pm

what is the auto-purge setting in pre-upgrade and post-upgrade?

Kryt0n · Post by **Kryt0n** » Tue Feb 21, 2012 9:09 pm

qt_ky wrote:The post says version 7.x... not so sure it's going to have XMETA.

-1 on me for failure to read... very hard to shift train of thought, particularly in my head! But still, give him something to think about I guess!

isulpova · Post by **isulpova** » Thu Mar 01, 2012 2:12 pm

I would also check auto-purge settings on specific job logs and at the project level. Make sure your job logs are not growing too large.

Autopurge is disabled for this project and all other projects on this server. The total of all logs for this project is about 1.5GB

What kind of migration occurred? A shift of existing jobs/executables or only jobs and re-compiled?
Is the XMETA on the same machine, or at least as close as it was before the migration?
Do scripts/processes/applications outside of datastage run as per pre-migration or noticeable changes elsewhere?

XMETA question is irrelevant due to pre-8 DS, I believe.

The scripts/processes/applications outside of datastage and most other DS projects rung noticeably faster.

Migration was that of the CPU server itself. Project did not get recompiled during migration. Later on it was recompiled as a measure against slow execution with no change in the execution time.

qt_ky · Post by **qt_ky** » Thu Mar 01, 2012 8:04 pm

Red flag: Leaving auto-purge disabled can be dangerous over time.

Did you check/count &PH& per project?

Are you saying CPUs were swapped out in-place? Old server is gone?

If it was done in place, was there any operating system adjustments for tuning OS settings?

Have you checked with support? I would present it as a new issue of long delays between jobs.

isulpova · Post by **isulpova** » Fri Mar 02, 2012 7:51 am

Red flag: Leaving auto-purge disabled can be dangerous over time.

Does the danger lays in size of the logs? If so, what would be the size where we should start worrying about performance?

Are you saying CPUs were swapped out in-place? Old server is gone?

Yes and yes.

If it was done in place, was there any operating system adjustments for tuning OS settings?

I will double check, but doubt it's possible to list or remember every minor adjustment.

Have you checked with support? I would present it as a new issue of long delays between jobs.

We contacted IBM tech support, if that's what you were asking, and the response was that 7.5 is no longer supported.

Mike · Post by **Mike** » Fri Mar 02, 2012 8:47 am

My understanding is that the EOS for version 7.5.2 and 7.5.3 is April 30, 2013, so you should still be able to get support for your issue as long as you're on one of those versions.

Mike

isulpova · Post by **isulpova** » Fri Mar 02, 2012 2:17 pm

I double checked and we actually run an older version of DS than I thought. It is, in fact, 6.0. So no tech support.

Separate question - does anybody think that purging the logs might have an effect? Is there a way to backup logs before removing them?

isulpova · Post by **isulpova** » Fri Mar 02, 2012 2:27 pm

What exactly happens in this "in-between" time after "Job finished" and before the next "Job run requested"? I see this is the part that slows down after the upgrade, and I am not sure what exactly is supposed to take place within this part of execution.

qt_ky · Post by **qt_ky** » Fri Mar 02, 2012 2:52 pm

Closing open files, appending entries to job logs, &PH& "stuff", related hashed file updates.

If a given job log data file or overflow file reaches the internal 2 GB limit then you will encounter problems. Likewise, if your file system fills up, you will encounter problems, not limited to corruption. Never purging job logs tends to slow down your job log view in Director.

I've mentioned it perhaps thrice now and provided a link to count &PH& records per project and tell you what find. Do you get a number like 1500? You may need to clear those.

Another simple thing to do, which may or may not help, is to reindex each project.

isulpova · Post by **isulpova** » Mon Mar 05, 2012 11:44 am

a link to count &PH& records per project and tell you what find.

Unfortunately, that part of the post is premium content, and I can't see it. Can you restate what it says? I'll have to make a request to my manager to pay for it but it'd take a while.

Another simple thing to do, which may or may not help, is to reindex each project.

How do I do that?

Another question on top of everything - Is there a way to back up logs? We want to purge them as suggested but management is nervous about loosing a history of runs.