Trace File Analysis

[davidnemirovsky]

I am trying to understand a particular section in a server-side trace file.

The 2 exerts are as follows.

Code: Select all

Exert 1:
0
   Arg4=pExecJobName=RunBatchJC.ETL_DEPRE_LOCN_TO_CC_SEQ
pParameterFile=/etl/QA2/parameters/datastage_master_parameters.txt
pParameterList=pBATCH_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pJOB_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pParameterList=pSOURCE_SYSTEM_CODE=MFG|pRESTART_IND=N|pPARAMETER_FILE=/etl/QA2/parameters/datastage_master_parameters.txt
2005-08-18 08:24:35: DSR_MESSAGE    =DSGetJobInfo: Returned Result = 24087
2005-08-18 08:36:29: DSR_MESSAGE    =DSGetJobInfo called: JobHandle = 2, InfoType = 1
2005-08-18 08:36:29: DSR_EXECJOB IN =
   Arg1=5
   Arg2=ExecJob.ETL_DEPRE_LOCN_TO_CC_SEQ
   Arg3=0
2005-08-18 08:36:29: DSR_EXECJOB OUT=
   Arg2=1\2005-08-18 08:24:01\0\10\-24087\0\\\24087\9\\
   Arg3=00_COMMON\UTILITY
Control job to run a job via the rExecJob routine.
1
0
0

Code: Select all

Exert 2:
0
   Arg4=pExecJobName=RunBatchJC.ETL_DEPRE_LOCN_TO_CC_SEQ
pParameterFile=/etl/QA2/parameters/datastage_master_parameters.txt
pParameterList=pBATCH_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pJOB_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pParameterList=pSOURCE_SYSTEM_CODE=MFG|pRESTART_IND=N|pPARAMETER_FILE=/etl/QA2/parameters/datastage_master_parameters.txt
2005-08-18 08:36:57: DSR_MESSAGE    =DSGetJobInfo: Returned Result = 24087
2005-08-18 08:52:32: DSR_MESSAGE    =DSGetJobInfo called: JobHandle = 2, InfoType = 1
2005-08-18 08:52:32: DSR_EXECJOB IN =
   Arg1=5
   Arg2=ExecJob.ETL_DEPRE_LOCN_TO_CC_SEQ
   Arg3=0
2005-08-18 08:52:32: DSR_EXECJOB OUT=
   Arg2=1\2005-08-18 08:24:01\0\10\-24087\0\\\24087\9\\
   Arg3=00_COMMON\UTILITY
Control job to run a job via the rExecJob routine.
1
0
0

Note the timestamps in the middle that wait for Exert1: 11 mins 54 secs and Exert2: 15 mins 35secs

This trace was done in the TEST project. The development project does not do this. Both environments are on the same physical server.

Any thoughts as to what could be causing this?

[ray.wurlod]

You haven't given us enough in the two excerpts. We need to see the preceding IN= and OUT= messages (and everything between them) to understand what DataStage was attempting to do that took so long.

[davidnemirovsky]

Ray, the trace file is quite large so I was just trying to keep the size of the post down. Please let me know if I have extracted enough of it this time. This is just more of Exert1. I suspect it's the same problem, but lets make sure I'm extracting enough of the trace before I post the 2nd exert.

Code: Select all

0
   Arg4=pExecJobName=RunBatchJC.ETL_DEPRE_LOCN_TO_CC_SEQ
pParameterFile=/etl/QA2/parameters/datastage_master_parameters.txt
pParameterList=pBATCH_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pJOB_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pParameterList=pSOURCE_SYSTEM_CODE=MFG|pRESTART_IND=N|pPARAMETER_FILE=/etl/QA2/parameters/datastage_master_parameters.txt
2005-08-18 08:24:31: DSR_MESSAGE    =DSGetJobInfo: Returned Result = 24087
2005-08-18 08:24:35: DSR_MESSAGE    =DSGetJobInfo called: JobHandle = 2, InfoType = 1
2005-08-18 08:24:35: DSR_EXECJOB IN =
   Arg1=5
   Arg2=ExecJob.ETL_DEPRE_LOCN_TO_CC_SEQ
   Arg3=0
2005-08-18 08:24:35: DSR_EXECJOB OUT=
   Arg2=1\2005-08-18 08:24:01\0\10\-24087\0\\\24087\9\\
   Arg3=00_COMMON\UTILITY
1
0
0




0
   Arg4=pExecJobName=RunBatchJC.ETL_DEPRE_LOCN_TO_CC_SEQ
pParameterFile=/etl/QA2/parameters/datastage_master_parameters.txt
pParameterList=pBATCH_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pJOB_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pParameterList=pSOURCE_SYSTEM_CODE=MFG|pRESTART_IND=N|pPARAMETER_FILE=/etl/QA2/parameters/datastage_master_parameters.txt
2005-08-18 08:24:35: DSR_MESSAGE    =DSGetJobInfo: Returned Result = 0
2005-08-18 08:24:35: DSR_MESSAGE    =DSGetJobInfo called: JobHandle = 2, InfoType = 10
2005-08-18 08:24:35: DSR_EXECJOB IN =
   Arg1=5
   Arg2=ExecJob.ETL_DEPRE_LOCN_TO_CC_SEQ
   Arg3=10
2005-08-18 08:24:35: DSR_EXECJOB OUT=
   Arg2=1\2005-08-18 08:24:01\0\10\-24087\0\\\24087\9\\
   Arg3=00_COMMON\UTILITY

1
0
0






0
   Arg4=pExecJobName=RunBatchJC.ETL_DEPRE_LOCN_TO_CC_SEQ
pParameterFile=/etl/QA2/parameters/datastage_master_parameters.txt
pParameterList=pBATCH_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pJOB_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pParameterList=pSOURCE_SYSTEM_CODE=MFG|pRESTART_IND=N|pPARAMETER_FILE=/etl/QA2/parameters/datastage_master_parameters.txt
2005-08-18 08:24:35: DSR_MESSAGE    =DSGetJobInfo: Returned Result = 24087
2005-08-18 08:36:29: DSR_MESSAGE    =DSGetJobInfo called: JobHandle = 2, InfoType = 1
2005-08-18 08:36:29: DSR_EXECJOB IN =
   Arg1=5
   Arg2=ExecJob.ETL_DEPRE_LOCN_TO_CC_SEQ
   Arg3=0
2005-08-18 08:36:29: DSR_EXECJOB OUT=
   Arg2=1\2005-08-18 08:24:01\0\10\-24087\0\\\24087\9\\
   Arg3=00_COMMON\UTILITY

1
0
0





0
   Arg4=pExecJobName=RunBatchJC.ETL_DEPRE_LOCN_TO_CC_SEQ
pParameterFile=/etl/QA2/parameters/datastage_master_parameters.txt
pParameterList=pBATCH_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pJOB_NAME=ETL_DEPRE_LOCN_TO_CC_SEQ|pParameterList=pSOURCE_SYSTEM_CODE=MFG|pRESTART_IND=N|pPARAMETER_FILE=/etl/QA2/parameters/datastage_master_parameters.txt
2005-08-18 08:36:29: DSR_MESSAGE    =DSGetJobInfo: Returned Result = 0
2005-08-18 08:36:29: DSR_MESSAGE    =DSGetJobInfo called: JobHandle = 2, InfoType = 10
2005-08-18 08:36:29: DSR_EXECJOB IN =
   Arg1=5
   Arg2=ExecJob.ETL_DEPRE_LOCN_TO_CC_SEQ
   Arg3=10
2005-08-18 08:36:29: DSR_EXECJOB OUT=
   Arg2=1\2005-08-18 08:24:01\0\10\-24087\0\\\24087\9\\
   Arg3=00_COMMON\UTILITY

1
0
0