Home > CICSPlex SM, debug > CICSPlex SM traces

CICSPlex SM traces

To an experienced CICS user, CICSPlex SM traces can seem weird compared to ‘vanilla’ CICS traces, so I am going to try and explain what is going on with them.

First a little bit of history

When CICSPlex SM was first introduced it was a separately orderable product – it was not part of the CICS TS package (the CICS TS package did not exist!). Because of this, the CICSPlex SM developers had to play by the rules (to keep the IBM lawyers happy), in that it had to use only published CICS interfaces, e.g. using the standard CICS APIs/SPIs and only programming interfaces that could be determined from the publicly available CICS documentation.

As the interface into CICS tracing is EXEC CICS ENTER TRACENUM, that is what CICSPlex SM uses to write trace records. This is also why CICSPlex SM trace records appear to CICS as so called ‘user’ trace records.

Super! Smashing! Great! so they are just User trace records?

Well yes, but if it was that simple I wouldn’t need this post.

As handy as the EXEC CICS ENTER TRACENUM request is, it is rather basic, in that it only has one ‘FROM’ area, meaning that if we had a trace point where we wanted to dump out multiple control blocks, we would need to issue multiple EXEC CICS ENTER TRACENUM requests.

So rather than using multiple requests for multiple control blocks, the CICSPlex SM trace component packages the control blocks that are to be traced into a single trace control block. The trace component can then deliver this payload in a single EXEC CICS ENTER TRACENUM request. Note however if the payload is bigger then the maximum amount of data that can be traced in one call, multiple EXEC CICS ENTER TRACENUM requests may still be issued.

How to annoy the IBM support teams

Well, I am sure you can think of plenty of ways to do this by yourself, but for members of the CICSPlex SM support teams, a really great way to annoy them is to print out a CICSPlex SM trace using the standard CICS trace formatter (DFHTUnnn). Why? Well as mentioned previously, the CICSPlex SM control blocks to be traced are packaged up in the user trace entry. The CICS trace formatter does not understand the CICSPlex SM payload, so you would get something like: (note this is truncated to fit)

AP 0008 USER  *EXCU - APPLICATION-PROGRAM-EXCEPTION - BadLCNVB - .*..CLCS.{..XLOPBadLCNVBB...9.S..B...LNCSMV30IYEGZGC0B......       
                                                                                                                                    
              TASK-02682 KE_NUM-016F TCB-QR   /009BBE88 RET-8009AC4C TIME-15:03:02.2616394272 INTERVAL-00.0004026875        =016454=
                1-0000  E4E2C5D9 C5E7C3                                                           *USEREXC                         *
                2-0000  0A5CFF00 C3D3C3E2 08C00035 E7D3D6D7  C28184D3 C3D5E5C2 C27470B0 F9B1E256  *.*..CLCS.{..XLOPBadLCNVBB...9.S.*
                  0020  01C20000 00D3D5C3 E2D4E5F3 F0C9E8C5  C7E9C7C3 F0C27470 B0EE0465 11000A7A  *.B...LNCSMV30IYEGZGC0B.........:*
                  0040  C3D6D401 00000000 00C3D400 000D693A  40000000 00001312 D00000D4 85A388D5  *COM......CM..... .......}..MethN*
                  0060  81948500 00000900 00000016 D4E07D00  000009C3 D3C3E26B E7D3D6D7 E2E3D2C6  *ame.........M\'....CLCS,XLOPSTKF*
                  0080  D9D44040 000006A0 00000000 16D4D688  000006A0 000006A0 16D4D540 16D4DD28  *RM  .........MOh.........MN .M..*
                  00A0  15EFA90E 15EFA680 00000001 16D4DC78  00010000 16671160 16672160 16AD2848  *..z...w......M.........-...-....*
                  00C0  16B42459 16673160 16B42600 16B42438  16B42380 00047000 16C0D7AC 00000000  *.......-.................{P.....*
                  00E0  00000000 00000000 00000000 00000000  00000000 00000000 00000000 00000000  *................................*
                  0100  00000000 00000000 00000000 00000000  00000000 00000000 96673CDE 16671596  *........................o......o*
                  0120  00000000 16D4D518 0005A394 16B450D0  16D4D018 E7D3D6D7 0180C3D3 C3E208C0  *.....MN...tm..&}.M}.XLOP..CLCS.{*
                  0140  16D4DC78 16671120 16671120 16315560  00047000 00000000 01010000 800A277A  *.M.............-...............:*
                  0160  000A1E28 C2747E07 15747E51 00000000  00000000 00000000 00000000 00000000  *....B.=...=.....................*
                  0180  00000000 00000000 E4D2F2F7 F3F7F240  E2E3C1D2 00000000 00000000 96671330  *........UK27372 STAK........o...*
                  01A0  0005A330 16671120 9667134E 16D4D398  16B42380 966728B6 00047000 96671404  *..t.....o..+.MLq....o.......o...*
                  01C0  16B423F8 16316260 0005A330 00000000  00000000 00000000 00000000 00000000  *...8...-..t.....................*
                  01E0  00000000 00000000 96672D56 00000000  966726FC 00000000 00000000 966717DC  *........o.......o...........o...*
                  0200  16B4239A 16673160 0005A330 16B42438  00000000 00000000 00000000 00000000  *.......-..t.....................*

-SNIP-                                                                                                                                         
                  0A40  00000018 F0F0F0F0 F0F0F2C4 00000000  00000000 00000000 00000000           *....0000002D................    *     
                3-0000  C28184D3 C3D5E5C2                                                         *BadLCNVB                        *     

Where as the CICSPlex SM trace formatter (EYU9XZUT) would output the following from the same record: (note this is truncated to fit)

 TASK:03071  METHOD:CLCS   PRIOR:XLOP  DEBUG:BadLCNVB  POINTID:    53  TRANID:LNCS                      SEQ:       402         
             MAJOBJ:COM    ENVRN:CMAS  TYPE:EXCEPTION  TOD:16:03:03.73001    CLOCK:15:03:03.73001  DATE: 5/27/08               
             UOW(CPSM):    SYSTM:MV30  NAME:IYEGZGC0   CICS-TASK:  71  TASK-START:15:03:03.67137                               
                                                                                                                               
         MethName  CLCS,XLOP                                                                                                   
                                                                                                                               
         STKFRM     LEN:0006A0     ALET:00000000 ADDR:16D4D688                                                                 
                0 - 000006A0 16D4D540 16D4DD28 15EFA90E  15EFA680 00000001 16D4DC78 00010000 *.....MN .M....z...w......M......*
               20 - 16671160 16672160 16AD2848 16B42459  16673160 16B42600 16B42438 16B42380 *...-...-...........-............*
               40 - 00047000 16C0D7AC 00000000 00000000  00000000 00000000 00000000 00000000 *......P.........................*
               60 - 00000000 00000000 00000000 00000000  00000000 00000000 00000000 00000000 *................................*
               80 - 00000000 96673CDE 16671596 00000000  16D4D518 0005A394 16B450D0 16D4D018 *....o......o.....MN...tm..&..M..*
               A0 - E7D3D6D7 0180C3D3 C3E208C0 16D4DC78  16671120 16671120 16315560 00047000 *XLOP..CLCS...M.............-....*
               C0 - 00000000 01010000 800A277A 000A1E28  C2748B71 B3A54856 00000000 00000000 *...........:....B....v..........*
               E0 - 00000000 00000000 00000000 00000000  00000000 E4D2F2F7 F3F7F240 E2E3C1D2 *....................UK27372 STAK*
-SNIP-                                                                                                                         
              680 - C3C2C3D6 D5E5C3D3 C3C2D7D9 D6E30000  00000000 00000000 00000000 00003000 *CBCONVCLCBPROT..................*
                                                                                                                               
         MAL        LEN:000028     ALET:00000000 ADDR:16C0D7AC                                                                 
             EYUQCLCS IN                                                                                                       
                *FUN FUNCTION( CCPICSLM )                                                                                      
                *CHR DEBUG( CSACCLCS )                                                                                         
                *PTR LINK_SET_DESCRIPTOR( 16B42380 )                                                                           
                *PTR STARTER_ECB( 95F6BFF0 )                                                                                   
             OUT                                                                                                               
                *RSP RESPONSE( OK )                                                                                            
                *RSN REASON( *             )                                                                                   
                                                                                                                               
         LSETD      LEN:0000B8     ALET:00000000 ADDR:16B42380                                                                 
                0 - 00B86EC5 E8E4C3E2 C5E8E4D9 C3D3E2C4  08000200 00000000 00010100 00000001 *..>EYUCSEYURCLSD................*
               20 - 00000001 00000000 00000000 00000000  00000000 00000080 00000000 00000000 *................................*
               40 - 00000000 00000000 16B42438 FFFFFF8D  16B42540 FFFFFF8D 16D4D398 00000000 *................... .....MLq....*
               60 - 00000000 00000000 00000000 FFFFFF8E  00000000 FFFFFF8E 00000000 00000000 *................................*
               80 - 00000000 00000000 000000F8 00000001  1636131C 00000000 000000F8 00000001 *...........8...............8....*
               A0 - 163612C4 00000000 000000F8 00000001  163612F0 00000000                   *...D.......8.......0....        *
                                                                                                                               
         CLCBASES   LEN:000098     ALET:00000000 ADDR:16B42438                                                                 
                0 - 00986EC5 E8E4C3E2 C5E8E4D9 C3D3C3C2  08000200 00000000 00000000 16B42380 *.q>EYUCSEYURCLCB................*
               20 - 01000100 E2C7C3F0 E2C5D5C4 16B42540  C2747E1B 8C3EE356 16B424D0 16B42600 *....SGC0SEND... B.=...T.........*
               40 - 16B42618 C9E8C3E2 E9C7C3F0 C9E8C3E2  E9C7C3F0 00000000 00000000 00000000 *....IYCSZGC0IYCSZGC0............*
               60 - 00000000 00000000 00000000 00000000  00000000 00000000 00000000 00000000 *................................*
               80 - 00000000 00000000 00000000 00000000  00000000 00000000                   *........................        *
                                                                                                                               
         CLCBASER   LEN:000098     ALET:00000000 ADDR:16B42540                                                                 
                0 - 00986EC5 E8E4C3E2 C5E8E4D9 C3D3C3C2  08000200 00000000 00000000 16B42380 *.q>EYUCSEYURCLCB................*
               20 - 02000100 E2C7C3F0 E2C5D5C4 16B42438  00000000 00000000 16B425D8 16B42600 *....SGC0SEND...............Q....*
               40 - 16B42618 C9E8C3E2 E9C7C3F0 C9E8C3E2  E9C7C3F0 00000000 00000000 00000000 *....IYCSZGC0IYCSZGC0............*
               60 - 00000000 00000000 00000000 00000000  00000000 00000000 00000000 00000000 *................................*
               80 - 00000000 00000000 00000000 00000000  00000000 00000000                   *........................        *
                                                                                                                               
         CLCBCONV   LEN:000070     ALET:00000000 ADDR:16B424D0                                                                 
                0 - 00000000 00000000 00000000 00000000  00000000 00000000 00000000 00000000 *................................*
               20 - 000000F8 00000001 16361794 00000000  000000F8 00000001 163617C0 00000000 *...8.......m.......8............*
               40 - 000000F8 00000001 16361768 00000000  00000000 00000000 00000000 00000000 *...8............................*
               60 - 00000000 00000000 00000000 00000000                                      *................                *

As you can see from the second (CICSPlex SM) output, the record is broken up into component pieces and more of it is interpreted. So using the appropriate trace formatter makes a big difference when trying to investigate an issue.

I can’t see that record in the CICS Trace Entries manual, where is it documented?

Umm, well actually CICSPlex SM trace points are not documented. Unlike CICS, CICSPlex SM has always been an OCO (Object Code Only) product and none of its control blocks have ever been documented. Also apart from Workload Management (WLM) and the CICSPlex SM API, user programs don’t normally have any kind of interactions with CICSPlex SM. This means there is less of a reason for CICS programmers to be able to read CICSPlex SM traces.

Well that is five minutes of my life I am not going to get back

So why would you ever want to use the CICSPlex SM trace formatter? Well you might want to:

  • Get symptoms or additional information for example debug text or trace point ids that may be documented in APARs which can help when searching IBM support.
  • Check a trace spans the correct date/time before sending to IBM support.
  • Investigate a WLM related problem.
  • Have a job handy, so that should IBM support ever need to access your system and perform remote diagnosis.

The CICSPlex SM trace format utility (EYU9XZUT) options are documented in the CICSPlex SM Problem Determination manual. Here is an example job:

//G8SHALTR JOB ,CLASS=A,MSGCLASS=H,NOTIFY=&SYSUID    
//*                                                  
//PRINTIT  EXEC PGM=EYU9XZUT,REGION=0M               
//STEPLIB  DD DISP=SHR,DSN=CICSTS.CPSM.SEYULOAD      
//SORTWK01 DD SPACE=(CYL,(30,30)),UNIT=SYSDA         
//SORTWK02 DD SPACE=(CYL,(30,30)),UNIT=SYSDA         
//SORTWK03 DD SPACE=(CYL,(30,30)),UNIT=SYSDA         
//SORTWK04 DD SPACE=(CYL,(30,30)),UNIT=SYSDA         
//SORTWK05 DD SPACE=(CYL,(30,30)),UNIT=SYSDA         
//SYSPRINT DD SYSOUT=*                               
//SYSOUT   DD SYSOUT=*                               
//TRCEABB  DD SYSOUT=*                               
//TRCEOUT  DD SYSOUT=*                               
//TRCEIN   DD DISP=SHR,DSN=MYCICS.DFHAUXT            
//SYSIN    DD *                                      
ABBREV                                               
FULL                                                 
/*                                                   
//                                                   

Note that the CICSPlex SM dump formatter EYU9Dnnn can be used to format CICSPlex SM trace entries in the CICS internal trace table in a dump.

Using the correct trace options

For a CMAS or CICSPlex SM Web User Interface (WUI) Server, the expectation is that CICS Aux trace is active all of the time! Now that may be a bit of a shock for some people, but don’t panic, the CICS master system trace flag should be switched off. This means that only CICSPlex SM user trace records and CICS exception trace records will be written, so the overheads are minimal. If you find that your CMAS or WUI server is constantly switching Aux trace datasets, chances are they are either very small, or there is a problem that needs to be investigated, or you are not use the correct trace options (which are:

INTTR=ON
SYSTR=OFF
USERTR=ON
AUXTR=ON

Which Auxtrace datasets?

If you have a problem with CICSPlex SM, and you call IBM, you will typically be asked for the complete CMAS and MAS joblogs and unformatted CICS Auxtrace datasets. One reason that you get asked for the CMAS Auxtrace datasets, even for MAS related problems, is that if CICSPlex SM communications is active between a MAS and a CMAS, then the CMAS will get sent a copy of all CICSPlex SM exceptions / special tracing that the MAS takes. When the CMAS receives these, they will then be written to the CMASes Auxtrace dataset. This is one of the reasons the CMAS always runs with Auxtrace active, to provide first failure data capture for CICSPlex SM problems for all of the MASes connected to it. (It is not practical to be running a MAS with CICS Auxtrace active all of the time).

Because the CMAS Auxtrace datasets can be so important, it is a good idea to manage them so that you do not accidentally loose trace data. For example if you are restarting a CMAS to try and resolve a problem, take a copy of the CMASes auxtrace datasets before restarting the CMAS so that you don’t loose any first failure data capture information when the CMAS restarts and reopens the auxtrace datasets. Some users have set up steps on the CMAS jobs to copy auxtrace datasets to a GDG for example.

Stop, Stop, to much!

Hopefully this rather long blog entry, has helped explain some of the reasons why CICSPlex SM tracing is different, or why IBM support asks you some of the questions that they do. If you have any questions on CICSPlex SM tracing, add a comment and I’ll do my best to answer.

Advertisements
Categories: CICSPlex SM, debug
  1. John Vousden
    June 19, 2008 at 11:17 pm

    Hi Grant! The article was of some interest though most of the recommendations for CICS Technical Support Programmers were known to me. You say we can use the CMAS Trace for WLM issues. I’d like to know where I can find some more out about that. By the way your suggestions about splitting our CPSM Production hub worked out very well ( see ETR 80376).

  2. Grant
    June 23, 2008 at 10:38 am

    Hi John,

    There is no formal documentation for CICSPlex SM WLM tracing, but try this WTSE which was produced by a couple of my service colleages – Mike and Tony.

    Cheers … Grant.used to logically delee

  1. February 3, 2012 at 2:58 am

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: