The part you missed is getting "step" time requires subtraction:
"step 2 completed time (in seconds)" - "step 1 completed time (in seconds)
Your job log should look something like this:
CPF1124 Information 00 06/22/15 05:15:00.031612 QWTPIIPP QSYS 04C0 *EXT *N
Message . . . . : Job 768524/QSYSOPR/LCP970C started on 06/22/15 at 05:15:00
in subsystem QINTER in QSYS. Job entered system on 06/22/15 at 05:15:00.
CPI1125 Information 00 06/22/15 05:15:00.032142 QWTPCRJA QSYS 0110 *EXT *N
Message . . . . : Job 768524/QSYSOPR/LCP970C submitted.
TIME REQUIRED FOR JOB SUBMISSION: 0.032142 - 0.00000 = 0.00032145 seconds
*NONE Request 06/22/15 05:15:00.033853 QWTSCSBJ *N QCMD QSYS 0195
From user . . . . . . . . . : QSYS
Message . . . . : -CALL PGM(LCP970C)
*NONE Command 06/22/15 05:15:00.049515 QCADRV QSYS 03C6 LCP970C BASLOC53 *STMT
To module . . . . . . . . . : LCP970C
To procedure . . . . . . . : LCP970C
Statement . . . . . . . . . : 13900
Message . . . . : 13900 - ADDLIBLE LIB(ARPEGGIOL) POSITION(*AFTER BASLOC53)
CPC2196 Completion 00 06/22/15 05:15:00.049614 QLICUSRL QSYS 0114 LCP970C BASLOC53 *STMT
To module . . . . . . . . . : LCP970C
To procedure . . . . . . . : LCP970C
Statement . . . . . . . . . : 13900
Message . . . . : Library ARPEGGIOL added to library list.
TIME REQUIRED TO ADD ARPEGGIOL TO JOB LIBRARY LIST: 0.00049614 - 0.00033835 = 0.00015779 seconds
It gets more complicated as you continue through job steps because minutes and hours will need to be converted to seconds . . .
-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of John R. Smith, Jr.
Sent: Friday, June 19, 2015 4:50 PM
To: 'Midrange Systems Technical Discussion'
Subject: RE: Seconds used question
I just submitted a job that calls 3 programs. I specified log level 4 0 *SECLVL. When I look at the joblog, I do not see anywhere that shows me how many CPU seconds each program used.
That is the most verbose logging that I know how to create. What am I missing?
-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of Gary Thompson
Sent: Friday, June 19, 2015 5:17 PM
To: Midrange Systems Technical Discussion
Subject: RE: Seconds used question
You need a more detailed or verbose job log which is generally controlled by the job description used to run the job.
On the CRTJOBD command, for example, In the Message logging section, you find "LOG Level"
If you press F1 to get help you will see:
Specifies the message logging values used to determine the amount
and type of information sent to the job log by this job. This
parameter has three elements: the message (or logging) level, the message severity, and the level of message text.
Sample starts
---------------------------------------------------------------
Element 1: Level
4
A message logging level of 4 is used for jobs that use this job
description.
0-4
Specify the message logging level to be used for the job's
messages.
0 No messages are logged.
1 All messages sent to the job's external message
queue with a severity greater than or equal to the
message logging severity are logged. This includes
the indications of job start, job end, and job
completion status.
2 The following information is logged:
o Logging level 1 information
o Request messages which result in a high-level
message with a severity code greater than or
equal to the message logging severity. Both the
request message and all associated messages are
logged.
Note: A high-level message is one that is sent
to the program message queue of the program that
receives the request message. For example, QCMD Sample ends
---------------------------------------------------------------
Well, that's just a sample, but level 4 creates the most detailed job log and that is not necessarily what you always want, but in this case it may be what you need.
Look at your IBM Systems management Work management manual
for more detail.
-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of John R. Smith, Jr.
Sent: Friday, June 19, 2015 2:31 PM
To: 'Midrange Systems Technical Discussion'
Subject: RE: Seconds used question
Where do I see the number of CPU seconds for each called program in a joblog? I've only seen a total at the end of the job. I can see elapsed time between calls but that doesn't help because I know the CPU was pegged (and not by this job) most of the time that this job was running.
-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of Gary Thompson
Sent: Friday, June 19, 2015 4:05 PM
To: Midrange Systems Technical Discussion
Subject: RE: Seconds used question
I'm not a performance or tuning expert.
My thoughts:
1 - review the tweak
2 - from your job log what steps used the most cpu ?
3 - can you compare to a job log made before the tweak ?
4 - maybe a more verbose job log could help ?
5 - use System I Navigator to look for recommended indexes (good general
practice)
6 - run a job in debug mode to get access path recommendations
-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of John R. Smith, Jr.
Sent: Friday, June 19, 2015 1:52 PM
To: 'Midrange Systems Technical Discussion'
Subject: RE: Seconds used question
I agree that it is CPU seconds but what miscellaneous CPU seconds are being charged to my job.
The question came from a job that ran the 403 seconds. A minor tweak was make to one of the programs and it used 10 times as many CPU seconds. The first run was on a light day and the second run was on a heavily abused day so before I totally blame the tweak, I want to make sure there wasn't a bunch of misc system functions such as swapping that got added to my CPU seconds and skewed the numbers.
-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of Gary Thompson
Sent: Friday, June 19, 2015 2:57 PM
To: Midrange Systems Technical Discussion
Subject: RE: Seconds used question
I don't know, but if you have a job log print file for that job, look at start and end times - a little math should answer your question and, if memory serves, the job log shows net cpu seconds.
-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of John R. Smith, Jr.
Sent: Friday, June 19, 2015 12:54 PM
To: midrange-l@xxxxxxxxxxxx
Subject: Seconds used question
The line in the joblog states
Job 999999/UUUUUUUUUU/JJJJJJJJJJ ended on 06/12/15 at02:36:42; 430.362 seconds used; end code 0
I have always thought this was CPU seconds used to execute the job but some questions have come up to make me wonder if it is more than that.
For example,
1) If the system is really bogged down and doing a lot of swapping,
does the CPU time spent swapping get added to this?
2) If the DASD is really bogged down, does that have any effect on this
number?
3) If there is a lock of a record and the program is in a LCKW state,
does that add any CPU overhead to my job (not sure if my program goes to sleep and the OS wakes it up when the lock frees or if my program is checking the lock status behind the scenes)?
Can someone provide a good explanation of this number and what else if anything other than my program instructions are included in it?
--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit:
http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at
http://archive.midrange.com/midrange-l.
--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit:
http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at
http://archive.midrange.com/midrange-l.
--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit:
http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at
http://archive.midrange.com/midrange-l.
--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit:
http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at
http://archive.midrange.com/midrange-l.
--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit:
http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at
http://archive.midrange.com/midrange-l.
--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit:
http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at
http://archive.midrange.com/midrange-l.
--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit:
http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at
http://archive.midrange.com/midrange-l.
midrange.com
