Understanding Job Logs

austin_316 · Post by **austin_316** » Mon Aug 31, 2015 2:44 am

Hi,
Please can anyone help me understand what is happening with my job logs.

We have a sequence in which we call 3 jobs and 3 shell scripts all called in a sequence one after the other.

Below is the summary of the sequence

LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Coordinator): Summary of sequence run
00:13:45: Sequence started (checkpointing on)
00:13:49: Exec_SB_ADA_FIN_STGOPS_1 (JOB SB_ADA_FIN_STGOPS_1.SZ) started
00:20:56: Exec_SB_ADA_FIN_STGOPS_1 (JOB SB_ADA_FIN_STGOPS_1.SZ) finished, status=2 [Finished with warnings]
00:20:57: Exec_SB_ADA_FIN_STGOPS_1_PostProcess (ROUTINE DSU.AfterJobRoutineAdaptiv) started
00:21:03: Exec_SB_ADA_FIN_STGOPS_1_PostProcess finished, reply=0
00:21:07: Exec_SB_ADA_FIN_OPSEXT_HEADER_1 (JOB SB_ADA_FIN_OPSEXT_HEADER_1.SZ) started
00:23:14: Exec_SB_ADA_FIN_OPSEXT_HEADER_1 (JOB SB_ADA_FIN_OPSEXT_HEADER_1.SZ) finished, status=1 [Finished OK]
00:23:15: Exec_SB_ADA_FIN_OPSEXT_HEADER_1_PostProcess (ROUTINE DSU.AfterJobRoutineAdaptiv) started
00:23:17: Exec_SB_ADA_FIN_OPSEXT_HEADER_1_PostProcess finished, reply=0
00:23:19: Exec_SB_ADA_FIN_OPSEXT_1 (JOB SB_ADA_FIN_OPSEXT_1.SZ) started
00:25:39: Exec_SB_ADA_FIN_OPSEXT_1 (JOB SB_ADA_FIN_OPSEXT_1.SZ) finished, status=2 [Finished with warnings]
00:25:39: Exec_SB_ADA_FIN_OPSEXT_1_PostProcess (ROUTINE DSU.AfterJobRoutineAdaptiv) started
00:25:45: Exec_SB_ADA_FIN_OPSEXT_1_PostProcess finished, reply=0
00:25:45: EXT_TRAILER (COMMAND sh /fods/ZA/PRD/IBM/Scratch/ODS/SCRIPTS/SZ/ADAPTIV_TRAILER.sh) started
00:25:50: EXT_TRAILER finished, reply=0
00:25:51: ADD_HDR_DELIM (COMMAND sh /fods/ZA/PRD/IBM/Scratch/ODS/SCRIPTS/SZ/AddHeaderEndDelimiter.sh) started
00:25:55: ADD_HDR_DELIM finished, reply=0
00:25:56: BATCH_SUCCESS (COMMAND /fods/ZA/PRD/IBM/Scratch/ODS/SCRIPTS/SZ/BATCH_RUN_UPDATE_SUCCESSV1.sh) started
00:25:58: BATCH_SUCCESS finished, reply=0
00:25:59: Sequence finished OK

When I observed the summary of the sequence, it mentions sequence started at 00:13:45. But when I login to director and check the first log was at 00:11:31 as shown in the job log below

DataStage Report - Detail Log for job: LD_EXTR_SEQ_SB_ADAPTIV.SZ
Produced on: 2015/08/31 10:28:00 AM
Project: SB_DOWNSTREAMS
Host system: PZACDSG1
Items: 1 - 70
Sorted on: Date Sorter

Item #: 1
Event ID: 420
Timestamp: 2015-08-22 00:11:31
Type: Control
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0070
Message: Starting Job LD_EXTR_SEQ_SB_ADAPTIV.SZ.
$STG_SRC_SCHEMA = user1
$STG_SRC_PWD = ********
$STG_SRC_SVR = USZKIL
$STG_SRC_USERNAME = user1
DSJobController = MSTR_SEQ_SB_ADAPTIV.SZ

Item #: 2
Event ID: 421
Timestamp: 2015-08-22 00:11:34
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0126
Message: Environment variable settings:
_=/usr/bin/nohup
APT_COMPILEOPT=-O -q64 -qtbtable=full -c
APT_COMPILER=/usr/vacpp/bin/xlC_r
APT_CONFIG_FILE=/home/dsg/IBM/InformationServer/Server/Configurations/default.apt
APT_LINKER=/usr/vacpp/bin/xlC_r
APT_LINKOPT=-G -q64
APT_MONITOR_MINTIME=10
APT_NO_ONE_NODE_COMBINING_OPTIMIZATION=1
APT_ORCHHOME=/home/dsg/IBM/InformationServer/Server/PXEngine
BELL=^G
CLCMD_PASSTHRU=1
DS_ENABLE_RESERVED_CHAR_CONVERT=0
DS_OPERATOR_BUILDOP_DIR=buildop
DS_OPERATOR_WRAPPED_DIR=wrapped
DS_OPTIMIZE_FILE_BROWSE=0
DS_TDM_PIPE_OPEN_TIMEOUT=720
DS_TDM_TRACE_SUBROUTINE_CALLS=0
DS_USERNO=-1462
DSHOME=/home/dsg/IBM/InformationServer/Server/DSEngine
DSIPC_OPEN_TIMEOUT=30
DSRPCD_PORT_NUMBER=31538
FLAVOR=-1
HOME=/
ISFSHMID=694157535
ISHOME=/home/dsg/IBM/InformationServer
ISUSER=isadmin
LANG=en_US
LC__FASTMSG=true
LDR_CNTRL=USERREGS
...
...
...
WHO=SB_DOWNSTREAMS

Item #: 3
Event ID: 422
Timestamp: 2015-08-22 00:13:45
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-E-0268
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ: Set NLS locale to US-ENGLISH,US-ENGLISH,US-ENGLISH,US-ENGLISH,US-ENGLISH

Item #: 4
Event ID: 423
Timestamp: 2015-08-22 00:13:45
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Coordinator): Starting new run of checkpointed Sequence job

Item #: 5
Event ID: 424
Timestamp: 2015-08-22 00:14:07
Type: RunJob
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0034
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ -> (SB_ADA_FIN_STGOPS_1.SZ): Job run requested
Mode (row/warn limits) = 0/0
Job Parameters --->
...
...
...

DSJobController=LD_EXTR_SEQ_SB_ADAPTIV.SZ

Item #: 6
Event ID: 425
Timestamp: 2015-08-22 00:14:09
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSRunJob): Waiting for job SB_ADA_FIN_STGOPS_1.SZ to start

Item #: 7
Event ID: 426
Timestamp: 2015-08-22 00:14:23
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSWaitForJob): Waiting for job SB_ADA_FIN_STGOPS_1.SZ to finish

Item #: 8
Event ID: 427
Timestamp: 2015-08-22 00:20:56
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSWaitForJob): Job SB_ADA_FIN_STGOPS_1.SZ has finished, status = 2 (Finished with warnings)

Item #: 9
Event ID: 428
Timestamp: 2015-08-22 00:20:56
Type: Warning
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_STGOPS_1): Job SB_ADA_FIN_STGOPS_1.SZ did not finish OK, status = 'Finished with warnings'

Item #: 10
Event ID: 429
Timestamp: 2015-08-22 00:20:56
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_STGOPS_1): Report on job: SB_ADA_FIN_STGOPS_1.SZ

**************************************************
STATUS REPORT FOR JOB: SB_ADA_FIN_STGOPS_1.SZ
Generated: 2015-08-22 00:20:56
Job start time=2015-08-22 00:14:20
Job end time=2015-08-22 00:20:52
Job elapsed time=00:06:32
Job status=2 (Finished with warnings)
Stage: STGSRC_FIN_ADA_Q, 193890 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:32, elapsed=00:05:17
Link: lnk_ReadRecords, 193890 rows
Stage: SB_MDM_BRANCH_CODES, 0 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:14, elapsed=00:04:59
Link: DSLink82, 0 rows
Stage: Lkp_MDMCodes, 193890 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:32, elapsed=00:05:17
Link: lnk_ReadRecords, 193890 rows
Link: DSLink82, 193890 rows
Link: lnk_GetRecords, 193890 rows
Stage: Trans_Validations, 193890 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:32, elapsed=00:05:17
Link: lnk_GetRecords, 193890 rows
Link: lnk_LoadRecords, 193890 rows
Link: Ln_STGOPS_ADA_ds, 193890 rows
Link: lnk_ACCT_NAME, 0 rows
Link: lnk_SB_AACT_NO, 0 rows
Link: lnk_SB_ACCT_TP, 0 rows
Link: lnk_SB_ACCR_INT, 0 rows
Link: lnk_SB_BAL, 0 rows
Link: lnk_SB_CLASS_CD, 0 rows
Link: lnk_SB_CNTRPARTY, 0 rows
Link: lnk_SB_CRNCY_CD, 0 rows
Link: lnk_SB_DT_LST_DEPO, 174849 rows
Link: lnk_SB_NOTNL, 0 rows
Link: lnk_SB_REF, 0 rows
Link: lnk_SB_TRD_DT, 0 rows
Stage: STGOPS_ADAPTIV, 193890 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:32, elapsed=00:05:17
Link: lnk_LoadRecords, 193890 rows
Stage: Fnl_ErrorRec, 174849 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:32, elapsed=00:05:17
Link: lnk_SB_REF, 0 rows
Link: lnk_SB_CRNCY_CD, 0 rows
Link: lnk_SB_NOTNL, 0 rows
Link: lnk_SB_TRD_DT, 0 rows
Link: lnk_SB_ACCT_TP, 0 rows
Link: lnk_SB_DT_LST_DEPO, 174849 rows
Link: lnk_ACCT_NAME, 0 rows
Link: lnk_SB_ACCR_INT, 0 rows
Link: lnk_SB_CNTRPARTY, 0 rows
Link: lnk_SB_AACT_NO, 0 rows
Link: lnk_SB_CLASS_CD, 0 rows
Link: lnk_SB_BAL, 0 rows
Link: lnk_ErrRecords, 174849 rows
Stage: ERROR_TYPE, 991 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:14, elapsed=00:04:59
Link: lnk_ReadErrRec, 991 rows
Stage: Lkp_ERRTYPEID_CRITICALITY, 174849 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:32, elapsed=00:05:17
Link: lnk_ErrRecords, 174849 rows
Link: lnk_ReadErrRec, 174849 rows
Link: lnk_LoadErrRec, 174849 rows
Stage: ERR_ADAPTIVE, 174849 rows input
Stage start time=2015-08-22 00:15:15, end time=2015-08-22 00:20:32, elapsed=00:05:17
Link: lnk_LoadErrRec, 174849 rows

Item #: 11
Event ID: 430
Timestamp: 2015-08-22 00:20:57
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_STGOPS_1): Checkpointed run of job 'SB_ADA_FIN_STGOPS_1.SZ'

Item #: 12
Event ID: 431
Timestamp: 2015-08-22 00:20:57
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Batch Name:SB_ADAPTIV

Item #: 13
Event ID: 432
Timestamp: 2015-08-22 00:20:57
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): JobName is: SB_ADA_FIN_STGOPS_1.SZ

Item #: 14
Event ID: 433
Timestamp: 2015-08-22 00:20:59
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): JobHand is: 2

Item #: 15
Event ID: 434
Timestamp: 2015-08-22 00:20:59
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Status of the Job is :2

Item #: 16
Event ID: 435
Timestamp: 2015-08-22 00:21:00
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Job LastTimeStamp is :2015-08-22 00:20:52

Item #: 17
Event ID: 436
Timestamp: 2015-08-22 00:21:00
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Job Run ID is: -3

Item #: 18
Event ID: 437
Timestamp: 2015-08-22 00:21:00
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Batch Run ID is: 2405

Item #: 19
Event ID: 438
Timestamp: 2015-08-22 00:21:00
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Source File name is /home/IBM/Scratch/ODS/SCRIPTS/SZ/SB_ADA_FIN_STGOPS_1.SZ.txt

Item #: 20
Event ID: 439
Timestamp: 2015-08-22 00:21:00
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Input and Output Records Count are: 193890 , 193890Respectively

Item #: 21
Event ID: 440
Timestamp: 2015-08-22 00:21:03
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Return Code of the script ERRJOB_UPDATE_SUCCESSV1.sh is :0

Item #: 22
Event ID: 441
Timestamp: 2015-08-22 00:21:03
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Output of the script ERRJOB_UPDATE_SUCCESSV1.sh is :
0 rows updated.

Item #: 23
Event ID: 442
Timestamp: 2015-08-22 00:21:03
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_STGOPS_1_PostProcess): Checkpointed call of routine 'DSU.AfterJobRoutineAdaptiv'

Item #: 24
Event ID: 443
Timestamp: 2015-08-22 00:21:17
Type: RunJob
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0034
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ -> (SB_ADA_FIN_OPSEXT_HEADER_1.SZ): Job run requested
Mode (row/warn limits) = 0/0
Job Parameters --->
..
..
..

DSJobController=LD_EXTR_SEQ_SB_ADAPTIV.SZ

Item #: 25
Event ID: 444
Timestamp: 2015-08-22 00:21:19
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSRunJob): Waiting for job SB_ADA_FIN_OPSEXT_HEADER_1.SZ to start

Item #: 26
Event ID: 445
Timestamp: 2015-08-22 00:21:36
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSWaitForJob): Waiting for job SB_ADA_FIN_OPSEXT_HEADER_1.SZ to finish

Item #: 27
Event ID: 446
Timestamp: 2015-08-22 00:23:14
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSWaitForJob): Job SB_ADA_FIN_OPSEXT_HEADER_1.SZ has finished, status = 1 (Finished OK)

Item #: 28
Event ID: 447
Timestamp: 2015-08-22 00:23:14
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_OPSEXT_HEADER_1): Report on job: SB_ADA_FIN_OPSEXT_HEADER_1.SZ

**************************************************
STATUS REPORT FOR JOB: SB_ADA_FIN_OPSEXT_HEADER_1.SZ
Generated: 2015-08-22 00:23:14
Job start time=2015-08-22 00:21:33
Job end time=2015-08-22 00:23:14
Job elapsed time=00:01:41
Job status=1 (Finished OK)
Stage: Row_Generator_15, 1 rows input
Stage start time=2015-08-22 00:22:53, end time=2015-08-22 00:23:08, elapsed=00:00:15
Link: lnk_ReadRecords, 1 rows
Stage: Trans_GenerateHeader, 1 rows input
Stage start time=2015-08-22 00:22:53, end time=2015-08-22 00:23:08, elapsed=00:00:15
Link: lnk_ReadRecords, 1 rows
Link: lnk_LoadRecords, 1 rows
Stage: Sequential_File_3, 1 rows input
Stage start time=2015-08-22 00:22:53, end time=2015-08-22 00:23:08, elapsed=00:00:15
Link: lnk_LoadRecords, 1 rows

Item #: 29
Event ID: 448
Timestamp: 2015-08-22 00:23:15
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_OPSEXT_HEADER_1): Checkpointed run of job 'SB_ADA_FIN_OPSEXT_HEADER_1.SZ'

Item #: 30
Event ID: 449
Timestamp: 2015-08-22 00:23:15
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Batch Name:SB_ADAPTIV

Item #: 31
Event ID: 450
Timestamp: 2015-08-22 00:23:15
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): JobName is: SB_ADA_FIN_OPSEXT_HEADER_1.SZ

Item #: 32
Event ID: 451
Timestamp: 2015-08-22 00:23:16
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): JobHand is: 3

Item #: 33
Event ID: 452
Timestamp: 2015-08-22 00:23:16
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Status of the Job is :1

Item #: 34
Event ID: 453
Timestamp: 2015-08-22 00:23:16
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Job LastTimeStamp is :2015-08-22 00:23:14

Item #: 35
Event ID: 454
Timestamp: 2015-08-22 00:23:16
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Job Run ID is: -3

Item #: 36
Event ID: 455
Timestamp: 2015-08-22 00:23:16
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Batch Run ID is: 2405

Item #: 37
Event ID: 456
Timestamp: 2015-08-22 00:23:16
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Source File name is /home/IBM/Scratch/ODS/SCRIPTS/SZ/SB_ADA_FIN_OPSEXT_HEADER_1.SZ.txt

Item #: 38
Event ID: 457
Timestamp: 2015-08-22 00:23:16
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Input and Output Records Count are: 1 , 1Respectively

Item #: 39
Event ID: 458
Timestamp: 2015-08-22 00:23:17
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Return Code of the script JOB_UPDATE_SUCCESSV1.sh is :0

Item #: 40
Event ID: 459
Timestamp: 2015-08-22 00:23:17
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Output of the script JOB_UPDATE_SUCCESSV1.sh is :
0 rows updated.

0 rows updated.

Item #: 41
Event ID: 460
Timestamp: 2015-08-22 00:23:17
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_OPSEXT_HEADER_1_PostProcess): Checkpointed call of routine 'DSU.AfterJobRoutineAdaptiv'

Item #: 42
Event ID: 461
Timestamp: 2015-08-22 00:23:23
Type: RunJob
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0034
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ -> (SB_ADA_FIN_OPSEXT_1.SZ): Job run requested
Mode (row/warn limits) = 0/0
Job Parameters --->
...
...
...

DSJobController=LD_EXTR_SEQ_SB_ADAPTIV.SZ

Item #: 43
Event ID: 462
Timestamp: 2015-08-22 00:23:25
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSRunJob): Waiting for job SB_ADA_FIN_OPSEXT_1.SZ to start

Item #: 44
Event ID: 463
Timestamp: 2015-08-22 00:23:37
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSWaitForJob): Waiting for job SB_ADA_FIN_OPSEXT_1.SZ to finish

Item #: 45
Event ID: 464
Timestamp: 2015-08-22 00:25:39
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (DSWaitForJob): Job SB_ADA_FIN_OPSEXT_1.SZ has finished, status = 2 (Finished with warnings)

Item #: 46
Event ID: 465
Timestamp: 2015-08-22 00:25:39
Type: Warning
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_OPSEXT_1): Job SB_ADA_FIN_OPSEXT_1.SZ did not finish OK, status = 'Finished with warnings'

Item #: 47
Event ID: 466
Timestamp: 2015-08-22 00:25:39
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_OPSEXT_1): Report on job: SB_ADA_FIN_OPSEXT_1.SZ

**************************************************
STATUS REPORT FOR JOB: SB_ADA_FIN_OPSEXT_1.SZ
Generated: 2015-08-22 00:25:39
Job start time=2015-08-22 00:23:34
Job end time=2015-08-22 00:25:38
Job elapsed time=00:02:04
Job status=2 (Finished with warnings)
Stage: Cpy_LoadRecords, 193890 rows input
Stage start time=2015-08-22 00:25:15, end time=2015-08-22 00:25:29, elapsed=00:00:14
Link: lnk_ReadRecords, 193890 rows
Link: lnk_LoadRecords, 193890 rows
Stage: bankingbook, 193890 rows input
Stage start time=2015-08-22 00:25:15, end time=2015-08-22 00:25:29, elapsed=00:00:14
Link: lnk_LoadRecords, 193890 rows

Item #: 48
Event ID: 467
Timestamp: 2015-08-22 00:25:39
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_OPSEXT_1): Checkpointed run of job 'SB_ADA_FIN_OPSEXT_1.SZ'

Item #: 49
Event ID: 468
Timestamp: 2015-08-22 00:25:40
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Batch Name:SB_ADAPTIV

Item #: 50
Event ID: 469
Timestamp: 2015-08-22 00:25:40
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): JobName is: SB_ADA_FIN_OPSEXT_1.SZ

Item #: 51
Event ID: 470
Timestamp: 2015-08-22 00:25:43
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): JobHand is: 4

Item #: 52
Event ID: 471
Timestamp: 2015-08-22 00:25:43
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Status of the Job is :2

Item #: 53
Event ID: 472
Timestamp: 2015-08-22 00:25:43
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Job LastTimeStamp is :2015-08-22 00:25:38

Item #: 54
Event ID: 473
Timestamp: 2015-08-22 00:25:43
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Job Run ID is: -3

Item #: 55
Event ID: 474
Timestamp: 2015-08-22 00:25:43
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Batch Run ID is: 2405

Item #: 56
Event ID: 475
Timestamp: 2015-08-22 00:25:43
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Source File name is /home/IBM/Scratch/ODS/SCRIPTS/SZ/SB_ADA_FIN_OPSEXT_1.SZ.txt

Item #: 57
Event ID: 476
Timestamp: 2015-08-22 00:25:43
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Input and Output Records Count are: 193890 , 193890Respectively

Item #: 58
Event ID: 477
Timestamp: 2015-08-22 00:25:45
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Return Code of the script JOB_UPDATE_SUCCESSV1.sh is :0

Item #: 59
Event ID: 478
Timestamp: 2015-08-22 00:25:45
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (1): Output of the script JOB_UPDATE_SUCCESSV1.sh is :
0 rows updated.

0 rows updated.

Item #: 60
Event ID: 479
Timestamp: 2015-08-22 00:25:45
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Exec_SB_ADA_FIN_OPSEXT_1_PostProcess): Checkpointed call of routine 'DSU.AfterJobRoutineAdaptiv'

Item #: 61
Event ID: 480
Timestamp: 2015-08-22 00:25:50
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@EXT_TRAILER): Executed: sh /home/IBM/Scratch/ODS/SCRIPTS/SZ/ADAPTIV_TRAILER.sh /home/IBM/Scratch/Outbounds/SZ/ADA dw.sz.bankingbook.20150821.12345678.dat
Reply=0
Output from command ====>

Item #: 62
Event ID: 481
Timestamp: 2015-08-22 00:25:51
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@EXT_TRAILER): Checkpointed execution of command 'sh /home/IBM/Scratch/ODS/SCRIPTS/SZ/ADAPTIV_TRAILER.sh'

Item #: 63
Event ID: 482
Timestamp: 2015-08-22 00:25:55
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@ADD_HDR_DELIM): Executed: sh /home/IBM/Scratch/ODS/SCRIPTS/SZ/AddHeaderEndDelimiter.sh /home/IBM/Scratch/Outbounds/SZ/ADA dw.sz.bankingbook.20150821.12345678.dat TEMP_FILE
Reply=0
Output from command ====>

Item #: 64
Event ID: 483
Timestamp: 2015-08-22 00:25:56
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@ADD_HDR_DELIM): Checkpointed execution of command 'sh /home/IBM/Scratch/ODS/SCRIPTS/SZ/AddHeaderEndDelimiter.sh'

Item #: 65
Event ID: 484
Timestamp: 2015-08-22 00:25:58
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@BATCH_SUCCESS): Executed: /home/IBM/Scratch/ODS/SCRIPTS/SZ/BATCH_RUN_UPDATE_SUCCESSV1.sh ods_dba_sz ******** PZACODS ods_dba_sz 2405
Reply=0
Output from command ====>

1 row updated.

Item #: 66
Event ID: 485
Timestamp: 2015-08-22 00:25:59
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@BATCH_SUCCESS): Checkpointed execution of command '/home/IBM/Scratch/ODS/SCRIPTS/SZ/BATCH_RUN_UPDATE_SUCCESSV1.sh'

Item #: 67
Event ID: 486
Timestamp: 2015-08-22 00:25:59
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Coordinator): Removed checkpoint record at successful completion of sequence

Item #: 68
Event ID: 487
Timestamp: 2015-08-22 00:25:59
Type: Info
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0019
Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Coordinator): Summary of sequence run
00:13:45: Sequence started (checkpointing on)
00:13:49: Exec_SB_ADA_FIN_STGOPS_1 (JOB SB_ADA_FIN_STGOPS_1.SZ) started
00:20:56: Exec_SB_ADA_FIN_STGOPS_1 (JOB SB_ADA_FIN_STGOPS_1.SZ) finished, status=2 [Finished with warnings]
00:20:57: Exec_SB_ADA_FIN_STGOPS_1_PostProcess (ROUTINE DSU.AfterJobRoutineAdaptiv) started
00:21:03: Exec_SB_ADA_FIN_STGOPS_1_PostProcess finished, reply=0
00:21:07: Exec_SB_ADA_FIN_OPSEXT_HEADER_1 (JOB SB_ADA_FIN_OPSEXT_HEADER_1.SZ) started
00:23:14: Exec_SB_ADA_FIN_OPSEXT_HEADER_1 (JOB SB_ADA_FIN_OPSEXT_HEADER_1.SZ) finished, status=1 [Finished OK]
00:23:15: Exec_SB_ADA_FIN_OPSEXT_HEADER_1_PostProcess (ROUTINE DSU.AfterJobRoutineAdaptiv) started
00:23:17: Exec_SB_ADA_FIN_OPSEXT_HEADER_1_PostProcess finished, reply=0
00:23:19: Exec_SB_ADA_FIN_OPSEXT_1 (JOB SB_ADA_FIN_OPSEXT_1.SZ) started
00:25:39: Exec_SB_ADA_FIN_OPSEXT_1 (JOB SB_ADA_FIN_OPSEXT_1.SZ) finished, status=2 [Finished with warnings]
00:25:39: Exec_SB_ADA_FIN_OPSEXT_1_PostProcess (ROUTINE DSU.AfterJobRoutineAdaptiv) started
00:25:45: Exec_SB_ADA_FIN_OPSEXT_1_PostProcess finished, reply=0
00:25:45: EXT_TRAILER (COMMAND sh /home/IBM/Scratch/ODS/SCRIPTS/SZ/ADAPTIV_TRAILER.sh) started
00:25:50: EXT_TRAILER finished, reply=0
00:25:51: ADD_HDR_DELIM (COMMAND sh /home/IBM/Scratch/ODS/SCRIPTS/SZ/AddHeaderEndDelimiter.sh) started
00:25:55: ADD_HDR_DELIM finished, reply=0
00:25:56: BATCH_SUCCESS (COMMAND /home/IBM/Scratch/ODS/SCRIPTS/SZ/BATCH_RUN_UPDATE_SUCCESSV1.sh) started
00:25:58: BATCH_SUCCESS finished, reply=0
00:25:59: Sequence finished OK

Item #: 69
Event ID: 488
Timestamp: 2015-08-22 00:26:04
Type: Control
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0077
Message: Finished Job LD_EXTR_SEQ_SB_ADAPTIV.SZ.

Item #: 70
Event ID: 489
Timestamp: 2015-08-22 00:26:04
Type: RunJob
User Name: dsadm
Message Id: IIS-DSTAGE-RUN-I-0066
Message: (MSTR_SEQ_SB_ADAPTIV.SZ) <- LD_EXTR_SEQ_SB_ADAPTIV.SZ: Job under control finished.

End of report.

But in the summary it mentions 00:13:45 which gives me a delay of about 2mins. Please can someone help me understand what happens between we triggering the sequence and the jobs inside are triggered.

Please advis if there is any more information I can provide on this. We already raised the issue with our internal datastage experts and they are speaking with IBM. But wanted to know from my side as well about the logs.

Thanks,
Ravi.

chulett · Post by **chulett** » Mon Aug 31, 2015 7:22 am

The 'delay' you are seeing is the amount of time from when the request to start the job was made and when it actually started. This log entry matches up with the summary:

Code: Select all

Item #: 4 
 Event ID: 423 
 Timestamp: 2015-08-22 00:13:45 
 Type: Info 
 User Name: dsadm 
 Message Id: IIS-DSTAGE-RUN-I-0019 
 Message: LD_EXTR_SEQ_SB_ADAPTIV.SZ.JobControl (@Coordinator): Starting new run of checkpointed Sequence job

austin_316 · Post by **austin_316** » Tue Sep 01, 2015 5:03 am

Hi Craig,
Thanks for the response.
Is there any way I can get the details why the job is starting after 2mins it was requested to run?

I am trying to understand this so that I can reduce this time, currently we have around 1500 jobs executing in different sets. Some times we obeserved that at a point of time around 25-30 jobs are running. Don't know if this will be reason for the delay.
We tried executing the jobs with same process/schedule in two different environments(Env1 and Env2 ). The Env2 is taking more time compared to Env1. All the jobs are finishing with in 1.5hrs on Env1 but it goes upto 4hr on Env2. There is not much difference in the data between these environments. But one of the differences we could find out is with number of allocated CPUs

Env1 was given entitled CPU 0.9 but is sitting in a shared pool of 4CPU. When we start executing the jobs we observed the usage is going till 3.5-3.7.
But Env2 was entitled CPU 2 and 2 is maximum CPU that it can use.

Can it be the reason for this behavior? We observed similar behavior in parallel jobs as well. If the jobs is triggered at 10:30:00 it takes atleast 1.5 to 2mins to show the first log of Subroutine called inside. But on Env1 it isn't the case

This difference in runtimes between environments causing issues as the expectation was that Env2 should also be running similar to Env1.

Apologies if my query is incorrect, but my intention was to understand what is happening

qt_ky · Post by **qt_ky** » Tue Sep 01, 2015 7:18 am

The entitled amount doesn't matter much. But you did point out that your env2 has double the CPU power as env1, so if the workload is CPU-demanding, then env1 jobs should run in about half the time as env2.

Also, if you are on version 9 or 11 (you mentioned 11), then you may be running up against the Workload Manager (WLM) thresholds. Go into the Operations Console and monitor what's going on in the Workload Manager tab. Are you running with the default settings or is somebody tweaking them?

austin_316 · Post by **austin_316** » Tue Sep 01, 2015 11:24 am

Hi,
We are running our jobs on 11.3 version in both the environments. Both the environments have WLM disabled. There is a datastage installation team who does the installations for us. Once they finish the installation and give box back to us, we import our jobs and start executing. So from our side we do not change much on the settings.
But if we have to check if both the environments have same settings where can we check it?