Abend 322 (time limit exceeded) using TC14

lstpierre · Post by **lstpierre** » Mon Sep 11, 2006 11:01 am

Hello all,

I am attempting to start Tomcat 5.0.28 with JDK 1.4.2 using JZOS 1.2.5.

I have not found a similar issue in this forum so here it is.

What I am getting is a S322 abend after 1m:16s of CPU has been reached on startup of the Tomcat Server. I have put debug="4" in conf/server.xml and conf/Catalina/localhost/*.xml.

The SYSOUT is normal and contains the following:

lstpierre · Post by **lstpierre** » Mon Sep 11, 2006 12:31 pm

By the way, for those interested, these are the messages in the STDERR after enabling FINE logging in the server properties:

»

lstpierre · Post by **lstpierre** » Tue Sep 12, 2006 9:23 am

By the way, I have changed my JZOS JCL to use version="14" instead of "50" so the messages appearing from JZOSVM50 are now from JZOSVM14. I regret to report that the wild loop persists. It seems that several threads are started and one of them could be looping, the ClassLoader looks OK from the FINE trace messages.

Cheers.

Post by **coz** » Tue Sep 12, 2006 11:14 am

Some of these startup problems have been related to a too small MAXFILEPROC setting. You might want to check your defaults. Here's a related thread:

http://www.dovetail.com/forum/viewtopic.php?t=277

lstpierre · Post by **lstpierre** » Wed Sep 13, 2006 7:55 am

Thanks, I will try that on a test system next week and post back the results here.

Louis.

lstpierre · Post by **lstpierre** » Mon Sep 18, 2006 2:52 pm

Problem not solved by increasing the MAXFILEPROC from 256 to 1024. The test have been run on Z/OS 1.7. The job still gets cancelled for CPU limit exceeded after a little more than two minutes with more than one minute of CPU used.

Here's the output of a D OMVS.O in case you might suggest other parms ajustments:

MAXPROCSYS = 200 MAXPROCUSER = 25
MAXFILEPROC = 1024 MAXFILESIZE = NOLIMIT
MAXCPUTIME = 1000 MAXUIDS = 50
MAXPTYS = 256
MAXMMAPAREA = 4096 MAXASSIZE = 41943040
MAXTHREADS = 10000 MAXTHREADTASKS = 5000
MAXCORESIZE = 4194304 MAXSHAREPAGES = 131072
IPCMSGQBYTES = 262144 IPCMSGQMNUM = 10000
IPCMSGNIDS = 500 IPCSEMNIDS = 500
IPCSEMNOPS = 25 IPCSEMNSEMS = 50
IPCSHMMPAGES = 10240 IPCSHMNIDS = 500
IPCSHMNSEGS = 10 IPCSHMSPAGES = 262144
SUPERUSER = XXXXXX FORKCOPY = COW
STEPLIBLIST =
USERIDALIASTABLE=
PRIORITYPG VALUES: NONE
PRIORITYGOAL VALUES: NONE
MAXQUEUEDSIGS = 1000 SHRLIBRGNSIZE = 67108864
SHRLIBMAXPAGES = 4096 VERSION = /
SYSCALL COUNTS = NO TTYGROUP = TTY
SYSPLEX = NO BRLM SERVER = N/A
LIMMSG = NONE AUTOCVT = OFF
RESOLVER PROC = TCPRESOL
AUTHPGMLIST = NONE
SWA = BELOW
SERV_LINKLIB =
SERV_LPALIB =

Thanks.

Post by **dovetail** » Tue Sep 19, 2006 7:33 am

What web applications are you running under Tomcat? Try removing all of them and restarting to see if the problem is due to one of the webapps.

Also, don't you get a JVM threaddump when the job is cancelled? Can you post the part that has the stacks so that we can see what threads are running?

lstpierre · Post by **lstpierre** » Tue Sep 19, 2006 12:01 pm

I have not yet configure any Tomcat Applications to run. This is an initial installation coming directly from the Tomcat distribution tar file.

Here is the tread stack from the JAVADUMP file:

1XMTHDINFO All Thread Details
NULL ------------------
NULL
2XMFULLTHDDUMP Full thread dump Classic VM (J2RE 1.4.2 IBM z/OS Persistent Reusable VM build cm142-20050929 (SR3), native threads):
3XMTHREADINFO "Thread-0" (TID:0xBA3B6F0, sys_thread_t:0xB800638, state:R, native ID:0xA6CBE50) prio=5
4XESTACKTRACE at com.dovetail.jzos.ZUtil.waitForMvsCommand(Native Method)
4XESTACKTRACE at com.dovetail.jzos.ZUtil.access$0(ZUtil.java:500)
4XESTACKTRACE at com.dovetail.jzos.ZUtil$MvsCommandThread.run(ZUtil.java:87)
3XHNATIVESTATE Native Thread State: SYSTEM RUNNING
3XHNATIVEDATA Native Stack Data: base: 14365e40 top: 0 pointer: 143e5e40 used(ebc9a1c0) free(143e5e40)
3XHMONITORHELD Monitors Held: (not implemented)
NULL
3XMTHREADINFO "Finalizer" (TID:0xBA3B8B0, sys_thread_t:0xAAE6930, state:CW, native ID:0xA6C9120) prio=8
4XESTACKTRACE at java.lang.Object.wait(Native Method)
4XESTACKTRACE at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
4XESTACKTRACE at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:160)
4XESTACKTRACE at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:225)
3XHNATIVESTATE Native Thread State: SYSTEM RUNNING
3XHNATIVEDATA Native Stack Data: base: 14271e40 top: 0 pointer: 142f1e40 used(ebd8e1c0) free(142f1e40)
3XHMONITORHELD Monitors Held: (not implemented)
NULL
3XMTHREADINFO "Reference Handler" (TID:0xBA3B908, sys_thread_t:0xAAE4D40, state:CW, native ID:0xA6C8210) prio=10
4XESTACKTRACE at java.lang.Object.wait(Native Method)
4XESTACKTRACE at java.lang.Object.wait(Object.java:443)
4XESTACKTRACE at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:142)
3XHNATIVESTATE Native Thread State: SYSTEM RUNNING
3XHNATIVEDATA Native Stack Data: base: 1425ce40 top: 0 pointer: 142dce40 used(ebda31c0) free(142dce40)
3XHMONITORHELD Monitors Held: (not implemented)
NULL
3XMTHREADINFO "Signal dispatcher" (TID:0xBA3B960, sys_thread_t:0xAAE0CC8, state:R, native ID:0xA6C7300) prio=5
3XHNATIVESTATE Native Thread State: SYSTEM RUNNING
3XHNATIVEDATA Native Stack Data: base: 14246e40 top: 0 pointer: 142c6e40 used(ebdb91c0) free(142c6e40)
3XHMONITORHELD Monitors Held: (not implemented)
NULL
3XMTHREADINFO "main" (TID:0xBA3B9B8, sys_thread_t:0xA935D00, state:R, native ID:0xA6C54E0) prio=5
4XESTACKTRACE at java.lang.ClassLoader.defineClass0(Native Method)
4XESTACKTRACE at java.lang.ClassLoader.defineClass(ClassLoader.java:810)
4XESTACKTRACE at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:147)
4XESTACKTRACE at java.net.URLClassLoader.defineClass(URLClassLoader.java:475)
4XESTACKTRACE at java.net.URLClassLoader.access$500(URLClassLoader.java(Compiled Code))
4XESTACKTRACE at java.net.URLClassLoader$ClassFinder.run(URLClassLoader.java(Compiled Code))
4XESTACKTRACE at java.security.AccessController.doPrivileged1(Native Method)
4XESTACKTRACE at java.security.AccessController.doPrivileged(AccessController.java(Compiled Code))
4XESTACKTRACE at java.net.URLClassLoader.findClass(URLClassLoader.java(Compiled Code))
4XESTACKTRACE at org.apache.catalina.loader.StandardClassLoader.findClass(StandardClassLoader.java:485)
4XESTACKTRACE at org.apache.catalina.loader.StandardClassLoader.loadClass(StandardClassLoader.java:820)
4XESTACKTRACE at org.apache.catalina.loader.StandardClassLoader.loadClass(StandardClassLoader.java(Compiled Code))
4XESTACKTRACE at org.apache.catalina.users.MemoryUserDatabaseFactory.getObjectInstance(MemoryUserDatabaseFactory.java:88)
4XESTACKTRACE at org.apache.naming.factory.ResourceFactory.getObjectInstance(ResourceFactory.java:129)
4XESTACKTRACE at javax.naming.spi.NamingManager.getObjectInstance(NamingManager.java:314)
4XESTACKTRACE at org.apache.naming.NamingContext.lookup(NamingContext.java:791)
4XESTACKTRACE at org.apache.naming.NamingContext.lookup(NamingContext.java:151)
4XESTACKTRACE at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.j
4XESTACKTRACE at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.j
4XESTACKTRACE at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.lifecycleEvent(GlobalResourcesLifecycleListener
4XESTACKTRACE at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
4XESTACKTRACE at org.apache.catalina.core.StandardServer.start(StandardServer.java:2306)
4XESTACKTRACE at org.apache.catalina.startup.Catalina.start(Catalina.java:556)
4XESTACKTRACE at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:85)
4XESTACKTRACE at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:58)
4XESTACKTRACE at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:60)
4XESTACKTRACE at java.lang.reflect.Method.invoke(Method.java:391)
4XESTACKTRACE at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:287)
4XESTACKTRACE at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:425)
3XHNATIVESTATE Native Thread State: USER RUNNING
3XHNATIVEDATA Native Stack Data: base: b9309e4 top: 0 pointer: b9b09e4 used(f46cf61c) free(b9b09e4)
3XHMONITORHELD Monitors Held: (not implemented)
NULL

If you can point me to some trace settings that would allow me to detect the source of the CPU wild loop, that be great.

Thanks again.

lstpierre · Post by **lstpierre** » Wed Sep 20, 2006 8:39 am

Since I had nothing to lose and I was on a test system I let the job run with no CPU limit using the JCL TIME parameter. Eventually Tomcat came up after about 2:00 min. of CPU time. After less than 24 hours running idle with no activity towards the Tomcat server the job has reached more than 5 min of CPU time.... Also, there is an indication of more than 3 millions records in JES Master for this job although all traces have been set to their default value and no sysout dataset (STDOUT,STDERR,etc...) contains such data.

So, I guess my question is has anyone else witnessed such behavior (CPU consumption) from the JZOS job running Tomcat.

Thanks for your attention.

Louis.

Post by **dovetail** » Thu Sep 21, 2006 8:54 am

I'm not sure what engine you are running on, but what you are seeing is not normal. My best guess is that there is an environment problem (most likely an LE problem) that is causing severely bad Java VM performance.

As a test, you might want to just run "HelloWorld" under JZOS and see what CPU is consumed. On my system, it takes:

CPU 0MIN 00.53SEC SRB 0MIN 00.00

If this is out of whack on your system, then try turning on the LE options: RPTOPTS(ON),RPTSTG(ON)

If you run this with LOGLVL='T' and send your (complete) job log output to info@dovetail.com, we'll try to look, but can't promise anything.

If HelloWorld is slow, your best bet would be to open a problem with the IBM support center.