On 14-Aug-2014 13:44 -0500, Steinmetz, Paul wrote:
With logging set to 4, 0, *MSG, Log CL *yes, could there be messages
that are within the job that don't appear in the joblog, thus filling
up the job message q, causing the message to wrap.
Yes. Not everything that will count against the JMQ storage will be
/visible/ in a displayed joblog, and not only because of filtering. A
formatted dump of the job's message queue might assist one to infer
something, with regard to the full-condition; no help for catching what
effects the spooling, though I already described in another reply how
finding the invoker of QMHJLOG processing can be done.
FWiW I recall similar cases whereby all joblogs _were_ caused by the
*PRTWRAP, and effectively only the last presented any data; all the
prior QPJOBLOG spools were either quite small or effectively empty. I
no longer recall the details, but supposing... Perhaps: • the jobs spent
most of their early processing doing requests that generated a large
number of both *Notify and automatic *Reply message types; possibly the
algorithm attempting to keep the JobMsgQ from filling does not work
aggressively against those message types. The database for example,
especially for I\O conditions, heavily relies on notify-messages and
their default replies; code that inserts into a unique key access path
will get a duplicate key exception manifest first as a notify and
default-cancel reply. • I really doubt that *Status messages sent to
*EXT account for filling the JMQ, but perhaps the request to CHGJOB
STSMSG(*NONE) [or as established at job initiation from the *USRPRF]
could matter.? • CL request messages may also be less aggressively
pruned, and while not visible per LOGCLPGM(*NO) [perhaps defined as an
attribute in the program, or changed\reset in the job during run-time
with CHGJOB], they may /fill/ the JMQ; thus a huge number of loops on a
CALL could quickly fill the JMQ, but per no logging of the actual *RQS
msg, the displayed joblog shows effectively nothing.
I may be completely mis-remembering, but I think the JMQ may be
initially divided into what are effectively /buckets/ whereby different
types of messages are deposited into their own buckets; probably at
least one bucket for each type [though some types might share a bucket]
is maintained as a minimum. As each new message arrives, according to
the MsgType the message is stored in the active bucket receiving that
type. If there is no active bucket, another bucket is carved-out.
Pruning likely occurs when there is no more room for the current message
in the respective bucket. A bucket purposed for a particular message
type [except probably a reserve bucket of some minimal size for each
message type] may be reclaimed to become a newly active bucket capable
of receiving new messages, if all of the specific type of the old
messages had been deleted from that assigned location\bucket; any bucket
that is found empty can be reused to start filling again with the same
message types or be re-purposed for another message type that is being
sent but has no room in any existing bucket. As I recall, that
implementation is reflected in messaging that warns about /many messages
of type &1/ are being sent repeatedly; thus the buckets are likely to
skew toward holding those types. One could imagine, if that were the
implementation, that any type of message that might not be /deleted/ in
the sense required to enable repurposing the buckets, might lead to what
might be described as a premature filling of a JMQ.
But then I should have seen 158 CPI2417 - Job message queue for
978872/TRP1/S001NITE19 has been wrapped.
I agree, *if* the origin of the other spooled joblog(s) were per the
Print Wrap (*PRTWRAP) effect. Again, likely easily determined what
effects each of the spooling requests using service\debug\addbkp\wrkjob.
There must be something else that I am missing.
Missing, are end-user tooling to help figure out what fills a JMQ.
The joblog spooling that occurs outside of *PRTWRAP and *ENDJOB are most
likely obtained using the Display Job Log (DSPJOBLOG) with
OUTPUT(*PRINT); I do not recall any callable methods\API to produce a
spooled joblog outside of that CL command. The _command exit_ features
and object auditing [for command-string] both can assist to find usages
in a particular job; and presumably also the invoking program.
FWiW: Might be interesting to review what SNDLOGMSG in TPIC08XXP is
doing; besides of course, the visible RETURN statement logged as a
request message, showing in the message quoted below. Interesting,
based solely on the apparent /Send Log Message/ moniker.
Regards, Chuck
Steinmetz, Paul on Thursday, August 14, 2014 2:11 PM wrote:
Same job on production LPAR does not wrap, only 1 joblog.
Logging is set the same on both LPARS.
Logging level is:
Message logging:
Level . . . . . . . . . . . . . . . . . . . . . : 4
Severity . . . . . . . . . . . . . . . . . . . : 0
Text . . . . . . . . . . . . . . . . . . . . . : *MSG
Log CL program commands . . . . . . . . . . . . . : *YES
Job log output . . . . . . . . . . . . . . . . . : *JOBEND
Creation times for the joblogs are every 21 seconds.
There is no overlap.
The beginning and end time of each message does not match the creation time of the QPJOBLOG.
Only the final 159 spoolfile matches.
The final joblog is 62 times larger (5,164 pages) then 2 thru 158 (81 pages)
CPF1124 Information 00 08/12/14 11:05:56.716813
QWTPIIPP QSYS 04C0 *EXT *N
Message: Job 978872/TRP1/S001NITE19 started on 08/12/14 at 11:05:56
*NONE Command 08/12/14 11:09:46.483656
QCADRV QSYS 03BA YOBSYSDTE TPNI08XXP 002B
Message: 2104 - RTVSYSVAL SYSVAL(QMINUTE) RTNVAR(&MINUTE)
*NONE Command 08/12/14 11:09:46.483700
QCADRV QSYS 03BA YOBSYSDTE TPNI08XXP 0032
Message: 2105 - RTVSYSVAL SYSVAL(QSECOND) RTNVAR(&SECOND)
*NONE Command 08/12/14 11:10:17.400577
QCLRTNE QSYS 0058 SNDLOGMSG TPIC08XXP 001D
Message: - RETURN /* RETURN due to end of CL program
*NONE Command 08/12/14 13:29:49.543490
QCADRV QSYS 03BA IGI0101CL TPIC08XXP 000F
Message: 2700 - RTVJOBA CURUSER(&USER)
CPF1164 Completion 00 08/12/14 14:04:29.274001
QWTMCEOJ QSYS 014A *EXT
Message: Job 978872/TRP1/S001NITE19 ended on 08/12/14 at 14:04:29;
midrange.com
