Wednesday, February 3, 2016

HPROF is your friend (if you REALLY have nothing else at hand)

Official Java 7 doc https://docs.oracle.com/javase/7/docs/technotes/samples/hprof.html
http://www.oracle.com/technetwork/java/javase/tooldescr-136044.html#gblvj Excellent also this article http://www.brendangregg.com/blog/2014-06-09/java-cpu-sampling-using-hprof.html

I am using this stupid class to test:
import java.util.HashMap;

public class CUT {
  public static void main(String[] args) {
    try {
      for (int i = 0; i < 10000; i++) {
         Thread.sleep(1);
         HashMap<String, Object> m = new HashMap<String, Object>();
         m.put("1", new Object());
      }
    }
    catch (Exception e) {
      e.printStackTrace();
    }
  }
}


then I run
javac -g CUT.java

java -agentlib:hprof=cpu=samples CUT

less java.hprof.txt 



this is what I get:

THREAD START (obj=50000193, id = 200001, name="main", group="main")
THREAD END (id = 200001)
THREAD START (obj=50000193, id = 200004, name="DestroyJavaVM", group="main")
THREAD END (id = 200004)
THREAD END (id = 200002)
TRACE 300050:
        java.lang.Thread.sleep(Thread.java:Unknown line)
        CUT.main(CUT.java:7)
TRACE 300014:
        sun.usagetracker.UsageTrackerClient.getPropertyPrivileged(UsageTrackerClient.java:136)
        sun.usagetracker.UsageTrackerClient.getPropertyPrivileged(UsageTrackerClient.java:132)
        sun.usagetracker.UsageTrackerClient.(UsageTrackerClient.java:109)
        sun.misc.PostVMInitHook.trackJavaUsage(PostVMInitHook.java:28)
TRACE 300026:
        java.lang.System.arraycopy(System.java:Unknown line)
        java.lang.String.getChars(String.java:826)
        java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:422)
        java.lang.StringBuffer.append(StringBuffer.java:272)
TRACE 300042:
        java.io.FilePermissionCollection.(FilePermission.java:711)
        java.io.FilePermission.newPermissionCollection(FilePermission.java:642)
        java.security.Permissions.getPermissionCollection(Permissions.java:254)
        java.security.Permissions.add(Permissions.java:132)
TRACE 300051:
        java.util.HashMap.putVal(HashMap.java:628)
        java.util.HashMap.put(HashMap.java:611)
        CUT.main(CUT.java:9)
TRACE 300052:
        java.util.HashMap.put(HashMap.java:611)
        CUT.main(CUT.java:9)
CPU SAMPLES BEGIN (total = 12) Wed Feb  3 06:07:50 2016
rank   self  accum   count trace method
   1 58.33% 58.33%       7 300050 java.lang.Thread.sleep
   2  8.33% 66.67%       1 300014 sun.usagetracker.UsageTrackerClient.getPropertyPrivileged
   3  8.33% 75.00%       1 300026 java.lang.System.arraycopy
   4  8.33% 83.33%       1 300042 java.io.FilePermissionCollection.
   5  8.33% 91.67%       1 300051 java.util.HashMap.putVal
   6  8.33% 100.00%       1 300052 java.util.HashMap.put
CPU SAMPLES END



Using the other option
java -agentlib:hprof=cpu=times CUT

gives me

THREAD START (obj=5000017d, id = 200002, name="HPROF gc_finish watcher", group="system")
THREAD START (obj=5000017d, id = 200001, name="main", group="main")
THREAD END (id = 200001)
THREAD START (obj=5000017d, id = 200003, name="DestroyJavaVM", group="main")
THREAD END (id = 200003)
THREAD END (id = 200002)
TRACE 301665:
        CUT.main(CUT.java:Unknown line)
TRACE 301663:
        java.util.HashMap.putVal(HashMap.java:Unknown line)
        java.util.HashMap.put(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 301664:
        java.util.HashMap.put(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 301657:
        java.util.HashMap.(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 301659:
        java.util.HashMap.hash(HashMap.java:Unknown line)
        java.util.HashMap.put(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 301661:
        java.util.HashMap.newNode(HashMap.java:Unknown line)
        java.util.HashMap.putVal(HashMap.java:Unknown line)
        java.util.HashMap.put(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 301660:
        java.util.HashMap.resize(HashMap.java:Unknown line)
        java.util.HashMap.putVal(HashMap.java:Unknown line)
        java.util.HashMap.put(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 301662:
        java.util.HashMap.afterNodeInsertion(HashMap.java:Unknown line)
        java.util.HashMap.putVal(HashMap.java:Unknown line)
        java.util.HashMap.put(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 300952:
        java.util.HashMap$Node.(HashMap.java:Unknown line)
        java.util.HashMap.newNode(HashMap.java:Unknown line)
        java.util.HashMap.putVal(HashMap.java:Unknown line)
        java.util.HashMap.put(HashMap.java:Unknown line)
TRACE 301656:
        java.util.AbstractMap.(AbstractMap.java:Unknown line)
        java.util.HashMap.(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 301658:
        java.lang.String.hashCode(String.java:Unknown line)
        java.util.HashMap.hash(HashMap.java:Unknown line)
        java.util.HashMap.put(HashMap.java:Unknown line)
        CUT.main(CUT.java:Unknown line)
TRACE 300163:
        java.lang.invoke.MethodHandle.(MethodHandle.java:Unknown line)
TRACE 300094:
        java.lang.invoke.MethodHandleImpl.(MethodHandleImpl.java:Unknown line)
        java.lang.invoke.MethodHandle.(MethodHandle.java:Unknown line)
TRACE 300252:
        java.lang.CharacterDataLatin1.getProperties(CharacterDataLatin1.java:Unknown line)
        java.lang.CharacterDataLatin1.toLowerCase(CharacterDataLatin1.java:Unknown line)
        java.lang.Character.toLowerCase(Character.java:Unknown line)
        java.lang.Character.toLowerCase(Character.java:Unknown line)
TRACE 301251:
        sun.misc.PerfCounter.(PerfCounter.java:Unknown line)
        sun.misc.PerfCounter.newPerfCounter(PerfCounter.java:Unknown line)
        sun.misc.PerfCounter$CoreCounters.(PerfCounter.java:Unknown line)
        sun.misc.PerfCounter.getReadClassBytesTime(PerfCounter.java:Unknown line)
CPU TIME (ms) BEGIN (total = 11886) Wed Feb  3 06:21:21 2016
rank   self  accum   count trace method
   1 94.75% 94.75%       1 301665 CUT.main
   2  1.10% 95.85%   10000 301663 java.util.HashMap.putVal
   3  0.83% 96.69%   10000 301664 java.util.HashMap.put
   4  0.75% 97.43%   10000 301657 java.util.HashMap.
   5  0.58% 98.01%   10000 301659 java.util.HashMap.hash
   6  0.41% 98.43%   10000 301661 java.util.HashMap.newNode
   7  0.27% 98.70%   10000 301660 java.util.HashMap.resize
   8  0.24% 98.93%   10000 301662 java.util.HashMap.afterNodeInsertion
   9  0.22% 99.15%   10016 300952 java.util.HashMap$Node.
  10  0.21% 99.36%   10000 301656 java.util.AbstractMap.
  11  0.15% 99.51%   10000 301658 java.lang.String.hashCode
  12  0.04% 99.55%       1 300163 java.lang.invoke.MethodHandle.
  13  0.02% 99.57%       1 300094 java.lang.invoke.MethodHandleImpl.
  14  0.02% 99.59%      80 300252 java.lang.CharacterDataLatin1.getProperties
  15  0.02% 99.60%       6 301251 sun.misc.PerfCounter.
CPU TIME (ms) END


which SEEMS much more accurate.
Heap Profiling uses this:
java -agentlib:hprof=heap=sites CUT
which gives (shortened form)
TRACE 300318:
        java.util.HashMap.resize(HashMap.java:703)
        java.util.HashMap.putVal(HashMap.java:628)
        java.util.HashMap.put(HashMap.java:611)
        CUT.main(CUT.java:9)

TRACE 300316:
        java.util.AbstractMap.(AbstractMap.java:73)
        java.util.HashMap.(HashMap.java:474)
        CUT.main(CUT.java:8)

TRACE 300186:
        java.util.HashMap$Node.(HashMap.java:284)
        java.util.HashMap.newNode(HashMap.java:1734)
        java.util.HashMap.putVal(HashMap.java:630)
        java.util.HashMap.put(HashMap.java:611)


(etc etc)

SITES BEGIN (ordered by live bytes) Wed Feb  3 06:28:22 2016
          percent          live          alloc'ed  stack class
 rank   self  accum     bytes objs     bytes  objs trace name
    1 39.18% 39.18%    800000 10000    800000 10000 300318 java.util.HashMap$Node[]
    2 23.51% 62.69%    480000 10000    480000 10000 300316 java.util.HashMap
    3 15.69% 78.38%    320384 10012    320384 10012 300186 java.util.HashMap$Node
    4  7.84% 86.22%    160000 10000    160000 10000 300317 java.lang.Object
    5  0.34% 86.56%      7000   53      7000    53 300011 char[]
    6  0.07% 86.63%      1504    4      1504     4 300001 java.lang.Thread
    7  0.06% 86.70%      1304   11      1304    11 300154 char[]
    8  0.06% 86.76%      1296    3      1296     3 300000 java.lang.Thread
    9  0.06% 86.82%      1248   11      1248    11 300172 char[]
   10  0.06% 86.88%      1248   11      1248    11 300173 char[]
   11  0.06% 86.94%      1240   10      1240    10 300176 char[]
   12  0.05% 86.99%      1040    1      1040     1 300021 java.lang.invoke.MethodHandle[]




To get help do:
java -agentlib:hprof=help

     HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code)

hprof usage: java -agentlib:hprof=[help]|[


Sunday, January 31, 2016

if you suffer of "slow favorites menu" in IE

if you suffer of "slow favorites menu" when you pass the mouse over, in IE, this fixed my problem:

In Control Panel, Folder Options, View tab, scroll to the bottom and uncheck “Show pop-up description for folders and desktop items”.
IE is a 1800 pound pig like this one http://weeklyworldnews.com/headlines/25815/1800-pound-pig/ , but please don't kill pigs, just use Firefox instead!


Tuesday, January 19, 2016

WebLogic deployment fails with java.lang.ArrayIndexOutOfBoundsException in com.bea.objectweb.asm.ClassReader.readClass

BEA-149205 Failed to initialize the application "BLA" due to error weblogic.application.ModuleException: 26
26
weblogic.application.ModuleException: 26
26
 at weblogic.servlet.internal.WebAppModule.createModuleException(WebAppModule.java:1824)
 at weblogic.servlet.internal.WebAppModule.init(WebAppModule.java:270)
 at weblogic.servlet.internal.WebAppModule.init(WebAppModule.java:682)
 at weblogic.application.internal.flow.ScopedModuleDriver.init(ScopedModuleDriver.java:162)
 at weblogic.application.internal.ExtensibleModuleWrapper.init(ExtensibleModuleWrapper.java:98)
 at weblogic.application.internal.flow.ModuleListenerInvoker.init(ModuleListenerInvoker.java:84)
 at weblogic.application.internal.flow.InitModulesFlow.initModule(InitModulesFlow.java:288)
 at weblogic.application.internal.flow.InitModulesFlow.initModules(InitModulesFlow.java:301)
 at weblogic.application.internal.flow.InitModulesFlow.prepare(InitModulesFlow.java:329)
 at weblogic.application.internal.BaseDeployment$1.next(BaseDeployment.java:706)
 at weblogic.application.utils.StateMachineDriver.nextState(StateMachineDriver.java:42)
 at weblogic.application.internal.BaseDeployment.prepare(BaseDeployment.java:237)
 at weblogic.application.internal.EarDeployment.prepare(EarDeployment.java:61)
 at weblogic.application.internal.DeploymentStateChecker.prepare(DeploymentStateChecker.java:158)
 at weblogic.deploy.internal.targetserver.AppContainerInvoker.prepare(AppContainerInvoker.java:61)
 at weblogic.deploy.internal.targetserver.AppDeployment.prepare(AppDeployment.java:155)
 at weblogic.management.deploy.internal.DeploymentAdapter$1.doPrepare(DeploymentAdapter.java:39)
 at weblogic.management.deploy.internal.DeploymentAdapter.prepare(DeploymentAdapter.java:191)
 at weblogic.management.deploy.internal.AppTransition$1.transitionApp(AppTransition.java:21)
 at weblogic.management.deploy.internal.ConfiguredDeployments.transitionApps(ConfiguredDeployments.java:240)
 at weblogic.management.deploy.internal.ConfiguredDeployments.prepare(ConfiguredDeployments.java:165)
 at weblogic.management.deploy.internal.ConfiguredDeployments.deploy(ConfiguredDeployments.java:122)
 at weblogic.management.deploy.internal.DeploymentServerService.resume(DeploymentServerService.java:210)
 at weblogic.management.deploy.internal.DeploymentServerService.start(DeploymentServerService.java:118)
 at weblogic.server.AbstractServerService.postConstruct(AbstractServerService.java:78)
 at sun.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:606)
 at org.glassfish.hk2.utilities.reflection.ReflectionHelper.invoke(ReflectionHelper.java:1017)
 at org.jvnet.hk2.internal.ClazzCreator.postConstructMe(ClazzCreator.java:388)
 at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:430)
 at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:456)
 at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:225)
 at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:82)
 at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2488)
 at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:98)
 at org.jvnet.hk2.internal.ServiceLocatorImpl.getService(ServiceLocatorImpl.java:606)
 at org.jvnet.hk2.internal.ThreeThirtyResolver.resolve(ThreeThirtyResolver.java:77)
 at org.jvnet.hk2.internal.ClazzCreator.resolve(ClazzCreator.java:231)
 at org.jvnet.hk2.internal.ClazzCreator.resolveAllDependencies(ClazzCreator.java:254)
 at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:413)
 at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:456)
 at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:225)
 at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:82)
 at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2488)
 at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:98)
 at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:87)
 at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.oneJob(CurrentTaskFuture.java:1162)
 at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.run(CurrentTaskFuture.java:1147)
 at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:548)
 at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
 at weblogic.work.ExecuteThread.run(ExecuteThread.java:263)
Caused By: java.lang.ArrayIndexOutOfBoundsException: 26
 at com.bea.objectweb.asm.ClassReader.readClass(Unknown Source)
 at com.bea.objectweb.asm.ClassReader.accept(Unknown Source)
 at com.bea.objectweb.asm.ClassReader.accept(Unknown Source)
 at weblogic.application.utils.annotation.ClassInfoImpl.(ClassInfoImpl.java:42)
 at weblogic.application.utils.annotation.ClassfinderClassInfos.polulateOneClassInfo(ClassfinderClassInfos.java:240)
 at weblogic.application.utils.annotation.ClassfinderClassInfos.populateClassInfos(ClassfinderClassInfos.java:193)
 at weblogic.application.utils.annotation.ClassfinderClassInfos.(ClassfinderClassInfos.java:44)
 at weblogic.servlet.internal.War.initializeClassInfosIfNecessary(War.java:446)
 at weblogic.servlet.internal.War.getAnnotatedClasses(War.java:376)
 at weblogic.servlet.utils.WarUtils.isJsfApplication(WarUtils.java:258)
 at weblogic.servlet.internal.WebAppModule.detectJsfApplication(WebAppModule.java:277)
 at weblogic.servlet.internal.WebAppModule.init(WebAppModule.java:262)
 at weblogic.servlet.internal.WebAppModule.init(WebAppModule.java:682)
 at weblogic.application.internal.flow.ScopedModuleDriver.init(ScopedModuleDriver.java:162)
 at weblogic.application.internal.ExtensibleModuleWrapper.init(ExtensibleModuleWrapper.java:98)
 at weblogic.application.internal.flow.ModuleListenerInvoker.init(ModuleListenerInvoker.java:84)
 at weblogic.application.internal.flow.InitModulesFlow.initModule(InitModulesFlow.java:288)
 at weblogic.application.internal.flow.InitModulesFlow.initModules(InitModulesFlow.java:301)
 at weblogic.application.internal.flow.InitModulesFlow.prepare(InitModulesFlow.java:329)
 at weblogic.application.internal.BaseDeployment$1.next(BaseDeployment.java:706)
 at weblogic.application.utils.StateMachineDriver.nextState(StateMachineDriver.java:42)
 at weblogic.application.internal.BaseDeployment.prepare(BaseDeployment.java:237)
 at weblogic.application.internal.EarDeployment.prepare(EarDeployment.java:61)
 at weblogic.application.internal.DeploymentStateChecker.prepare(DeploymentStateChecker.java:158)
 at weblogic.deploy.internal.targetserver.AppContainerInvoker.prepare(AppContainerInvoker.java:61)
 at weblogic.deploy.internal.targetserver.AppDeployment.prepare(AppDeployment.java:155)
 at weblogic.management.deploy.internal.DeploymentAdapter$1.doPrepare(DeploymentAdapter.java:39)
 at weblogic.management.deploy.internal.DeploymentAdapter.prepare(DeploymentAdapter.java:191)
 at weblogic.management.deploy.internal.AppTransition$1.transitionApp(AppTransition.java:21)
 at weblogic.management.deploy.internal.ConfiguredDeployments.transitionApps(ConfiguredDeployments.java:240)
 at weblogic.management.deploy.internal.ConfiguredDeployments.prepare(ConfiguredDeployments.java:165)
 at weblogic.management.deploy.internal.ConfiguredDeployments.deploy(ConfiguredDeployments.java:122)
 at weblogic.management.deploy.internal.DeploymentServerService.resume(DeploymentServerService.java:210)
 at weblogic.management.deploy.internal.DeploymentServerService.start(DeploymentServerService.java:118)
 at weblogic.server.AbstractServerService.postConstruct(AbstractServerService.java:78)
 at sun.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:606)
 at org.glassfish.hk2.utilities.reflection.ReflectionHelper.invoke(ReflectionHelper.java:1017)
 at org.jvnet.hk2.internal.ClazzCreator.postConstructMe(ClazzCreator.java:388)
 at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:430)
 at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:456)
 at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:225)
 at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:82)
 at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2488)
 at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:98)
 at org.jvnet.hk2.internal.ServiceLocatorImpl.getService(ServiceLocatorImpl.java:606)
 at org.jvnet.hk2.internal.ThreeThirtyResolver.resolve(ThreeThirtyResolver.java:77)
 at org.jvnet.hk2.internal.ClazzCreator.resolve(ClazzCreator.java:231)
 at org.jvnet.hk2.internal.ClazzCreator.resolveAllDependencies(ClazzCreator.java:254)
 at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:413)
 at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:456)
 at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:225)
 at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:82)
 at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2488)
 at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:98)
 at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:87)
 at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.oneJob(CurrentTaskFuture.java:1162)
 at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.run(CurrentTaskFuture.java:1147)
 at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:548)
 at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
 at weblogic.work.ExecuteThread.run(ExecuteThread.java:263)




In Oracle support I find that

Unable To Deploy An Application In WebLogic 12C That Works In WebLogic 10 (Doc ID 1565172.1)

WebLogic Server 12c (12.1.1 and higher) does a complete scan of all *.class files in an application when it is deployed. This is an enhancement over previous versions which prevents invalid Java classes being deployed with an application. However, in a few cases where there is an unused invalid class packaged with the application, deployment which succeeded in WLS 11g or earlier could fail in WebLogic 12c. See Note 1504269.1 for more information about a similar case. In that case, there was an invalid class file in the application being deployed. The problem wasn't caught by the previous JVM, but was caught in WLS 12.1.1. In the customer's case, there were files in the customer application which were not Java class files, but which were named with the .class extension. These files were scanned and validated on deployment of the application, and failed validation since they were not Java classes. This caused the deployment failure.


I restart the WLS server with -verbose:class, to find out that weblogic.application.utils.annotation.ClassfinderClassInfos is loaded from wlserver/modules/features/weblogic.server.merged.jar

I patch this class adding this println:
  private void polulateOneClassInfo(Source source)
    throws AnnotationProcessingException
  {
    if (source == null) {
      return;
    }
    System.out.println("polulateOneClassInfo: source=" + source.getURL().toString());



and I find out that the offending class is loaded from a JAR compiled with Java 1.4 (check the manifest.mf)

See also http://stackoverflow.com/questions/19152655/java-lang-arrayindexoutofboundsexception-while-deploying-app-in-wls-12