river-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Peter Firmstone <j...@zeus.net.au>
Subject Re: test failure repeatability
Date Mon, 01 Apr 2013 10:14:37 GMT
The attachments will be removed from the list, so I've cc'd you, anyone 
who's interested, let me know I can forward the attachments.  They can 
be opened with jvisualvm.

The profiling isn't perfect, the test runs for about 8.5 minutes, so 
hotspot should have kicked in relatively early in both test runs.

I guess a significant problem is; the more I remove performance 
impedances, like unnecessary DNS calls, the faster multithreading and 
context switching gets.

Not only did the old policy providers create contention, but it was 
slower for single threaded performance (I'll have to run the previous 
release branch for comparison when I get some time).

The URIGrant.implies call is now down to .228 ms per invocation, down 
from 1.68 ms per invocation this week, which was already quite good (on 
old UltraSparcII hardware), during stress tests this method is called 
almost 40,000 times.

In comparison the old policy provider which required a DNS call (every 
time CodeSource.implies is called, functionality now replaced by 
URIGrant.implies), the old policy provider also cached all Permission's 
in highly contended PermissionCollection's, which during network calls 
invoked SocketPermission.implies, possibly for every SocketPermission in 
the PermissionCollection, DNS is also consulted by 
SocketPermission.implies, while synchronized, ouch!

URIGrant.implies is non blocking, that's right zero contention.  
SocketPermission.implies DNS calls can be avoided in most cases if 
PermissionComparator finds an exact match or wild card.

This is without the CombinerSecurityManager, which improves security 
performance by a factor of 10 (SocketPermission is only checked once for 
each AccessControlContext).

PreferredClassProvider no longer creates unecessary DNS calls, and 
neither does SecureClassLoader,  URLClassLoader or PreferredClassLoader.

So the good news is the next release will feel much faster, the bad news 
is that existing concurrency bugs that previously didn't appear during 
test runs, but likely to manifest during production are now occurring 
during testing.  There's more good news, we fixed a number of 
concurrency bugs since the last release too, I guess I have to draw the 
line somewhere and cut a release.

DNS calls haven't been completely eliminated as some are still 
necessary, but a multitude of unnecessary DNS calls have been eliminated.

Regards,

Peter.

Peter Firmstone wrote:
> They've passed more consistently in the past, they're either 
> concurrency bugs or network timing related, it would be nice to at 
> least determine if it's the former or latter.
>
> Cheers,
>
> Peter.
>
> Tom Hobbs wrote:
>> Are these all new failures, i.e. were they working before?  Or are they
>> "new" failures in that the test categories have only recently been
>> reactivated and the failures discovered?
>>
>> Are they a big enough blocker to stop a release?
>>
>>
>> On Sun, Mar 31, 2013 at 11:31 PM, Peter Firmstone <jini@zeus.net.au> 
>> wrote:
>>
>>  
>>> The following test fails 30 times in a run of 130 tests:
>>>
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>> [java]  #       of      tests   passed  =       0
>>> [java]  #       of      tests   passed  =       1
>>>
>>>
>>>
>>>
>>>
>>>
>>>         100
>>>
>>>
>>>
>>>
>>> Buildfile: build.xml
>>>
>>> qa.run-tests:
>>>
>>> james-brown:
>>>   [delete] Deleting directory /opt/src/River_Fixed/**
>>> peterConcurrentPolicy/qa/soul
>>>    [mkdir] Created dir: /opt/src/River_Fixed/**
>>> peterConcurrentPolicy/qa/soul
>>>    [touch] Creating 
>>> /opt/src/River_Fixed/**peterConcurrentPolicy/qa/soul/*
>>> *soul.201303312239034808
>>>
>>> run-tests:
>>>     [java]
>>>     [java] ------------------------------**-----------
>>>     [java] CONFIGURATION FILE:
>>>     [java]
>>>     [java]    /opt/src/River_Fixed/**peterConcurrentPolicy/qa/src/**
>>> com/sun/jini/test/resources/**qaHarness.prop
>>>     [java]
>>>     [java] ------------------------------**-----------
>>>     [java] SETTING UP THE TEST LIST:
>>>     [java]
>>>     [java]    Adding test: 
>>> com/sun/jini/test/spec/**javaspace/conformance/
>>> **snapshot/**SnapshotExpirationNotifyTest.**td
>>>     [java]
>>>     [java] ------------------------------**-----------
>>>     [java] GENERAL HARNESS CONFIGURATION INFORMATION:
>>>     [java]
>>>     [java]    Date started:
>>>     [java]       Sun Mar 31 22:39:37 EST 2013
>>>     [java]    Installation directory of the JSK:
>>>     [java]       com.sun.jini.jsk.home=/opt/**src/River_Fixed/**
>>> peterConcurrentPolicy
>>>     [java]    Installation directory of the harness:
>>>     [java]       com.sun.jini.qa.home=/opt/src/**River_Fixed/**
>>> peterConcurrentPolicy/qa
>>>     [java]    Categories being tested:
>>>     [java]       categories=No Categories
>>>     [java] ------------------------------**-----------
>>>     [java] ENVIRONMENT PROPERTIES:
>>>     [java]
>>>     [java]    JVM information:
>>>     [java]       Java HotSpot(TM) Server VM, 20.5-b03, 32 bit VM mode
>>>     [java]       Sun Microsystems Inc.
>>>     [java]    OS information:
>>>     [java]       SunOS, 5.10, sparc
>>>     [java]
>>>     [java] ------------------------------**-----------
>>>     [java] STARTING TO RUN THE TESTS
>>>     [java]
>>>     [java]
>>>     [java] Running com/sun/jini/test/spec/**javaspace/conformance/**
>>> snapshot/**SnapshotExpirationNotifyTest.**td
>>>     [java] Time is Sun Mar 31 22:39:38 EST 2013
>>>     [java] Starting test in separate process with command:
>>>     [java] /usr/jdk/jdk1.6.0_30/jre/bin/**java
>>> -Djava.security.manager=org.**apache.river.api.security.**CombinerSecurityManager

>>>
>>> -Djava.security.policy=file:/**opt/src/River_Fixed/**
>>> peterConcurrentPolicy/qa/**harness/policy/defaulttest.**policy
>>> -Djava.rmi.server.codebase=htt**p://bluto:9082/qa1-javaspace-**dl.jar<http://bluto:9082/qa1-javaspace-dl.jar>-cp

>>> /opt/src/River_Fixed/
>>> **peterConcurrentPolicy/qa/lib/**jiniharness.jar:/opt/src/**River_Fixed/** 
>>>
>>> peterConcurrentPolicy/qa/lib/**jinitests.jar:/opt/src/River_**
>>> Fixed/peterConcurrentPolicy/**lib/jsk-platform.jar:/opt/src/**River_Fixed/ 
>>>
>>> **peterConcurrentPolicy/lib/jsk-**lib.jar:/opt/src/River_Fixed/**
>>> peterConcurrentPolicy/lib/**high-scale-lib.jar:/opt/src/**River_Fixed/** 
>>>
>>> peterConcurrentPolicy/lib/**custard-apple-1.0.2.jar -ea -esa -client
>>> -Djava.ext.dirs=/usr/jdk/jdk1.**6.0_30/jre/lib/ext:/usr/jdk/**
>>> packages/lib/ext:/opt/src/**River_Fixed/**peterConcurrentPolicy/qa/lib-** 
>>>
>>> ext:/opt/src/River_Fixed/**peterConcurrentPolicy/lib-ext
>>> -Dcom.sun.jini.jsk.port=9080 -Dcom.sun.jini.qa.port=9081
>>> -Dcom.sun.jini.jsk.home=/opt/**src/River_Fixed/**peterConcurrentPolicy
>>> -Dcom.sun.jini.qa.home=/opt/**src/River_Fixed/**peterConcurrentPolicy/qa 
>>>
>>> -Dcom.sun.jini.qa.harness.**harnessJar=/opt/src/River_**
>>> Fixed/peterConcurrentPolicy/**qa/lib/jiniharness.jar
>>> -Dcom.sun.jini.qa.harness.**testJar=/opt/src/River_Fixed/**
>>> peterConcurrentPolicy/qa/lib/**jinitests.jar 
>>> -Dcom.sun.jini.qa.harness.**runjiniserver=true
>>> -Dcom.sun.jini.qa.harness.**runkitserver=true 
>>> -Djava.security.properties=*
>>> *file:/opt/src/River_Fixed/**peterConcurrentPolicy/qa/**
>>> harness/trust/dynamic-policy.**properties 
>>> -Dcom.sun.jini.qa.harness.**testhosts=
>>> -Djava.util.logging.config.**file=/home/peter/logging.**properties
>>> -Dcom.sun.jini.test.home=/opt/**src/River_Fixed/**peterConcurrentPolicy/qa 
>>>
>>> -Dcom.sun.jini.test.port=9082 -Dcom.sun.jini.qa.harness.**
>>> policies=file:/opt/src/River_**Fixed/peterConcurrentPolicy/**
>>> qa/src/com/sun/jini/test/**resources/jinitest.policy
>>> -Djava.ext.dirs=/usr/jdk/jdk1.**6.0_30/jre/lib/ext:/usr/jdk/**
>>> packages/lib/ext:/opt/src/**River_Fixed/**peterConcurrentPolicy/qa/lib-** 
>>>
>>> ext:/opt/src/River_Fixed/**peterConcurrentPolicy/lib-ext
>>> com.sun.jini.qa.harness.**MasterTest com/sun/jini/test/spec/**
>>> javaspace/conformance/**snapshot/**SnapshotExpirationNotifyTest.**td
>>>     [java] com.sun.jini.qa.harness.**TestException: Not all 
>>> listeners've
>>> got expected number of events.
>>>     [java]     at com.sun.jini.test.spec.**javaspace.conformance.**
>>> snapshot.**SnapshotExpirationNotifyTest.**run(**
>>> SnapshotExpirationNotifyTest.**java:370)
>>>     [java]     at 
>>> com.sun.jini.qa.harness.**MasterTest.doTest(MasterTest.*
>>> *java:256)
>>>     [java]     at 
>>> com.sun.jini.qa.harness.**MasterTest.main(MasterTest.**
>>> java:144)
>>>     [java]
>>>     [java] TIME: 10:42:54 PM
>>>     [java]
>>>     [java] Test process was destroyed and returned code 1
>>>     [java] com/sun/jini/test/spec/**javaspace/conformance/**snapshot/**
>>> SnapshotExpirationNotifyTest.**td
>>>     [java] Test Failed: Test Failed: 
>>> com.sun.jini.qa.harness.**TestException:
>>> Not all listeners've got expected number of events.
>>>     [java]
>>>     [java]
>>>     [java] ------------------------------**-----------
>>>     [java]
>>>     [java] SUMMARY ==============================**===
>>>     [java]
>>>     [java] com/sun/jini/test/spec/**javaspace/conformance/**snapshot/**
>>> SnapshotExpirationNotifyTest.**td
>>>     [java] Test Failed: Test Failed: 
>>> com.sun.jini.qa.harness.**TestException:
>>> Not all listeners've got expected number of events.
>>>     [java]
>>>     [java] ------------------------------**-----------
>>>     [java]
>>>     [java] # of tests started   = 1
>>>     [java] # of tests completed = 1
>>>     [java] # of tests passed    = 0
>>>     [java] # of tests failed    = 1
>>>     [java]
>>>     [java] ------------------------------**-----------
>>>     [java]
>>>     [java]    Date finished:
>>>     [java]       Sun Mar 31 22:42:59 EST 2013
>>>     [java]    Time elapsed:
>>>     [java]       201 seconds
>>>     [java]
>>>     [java] Java Result: 1
>>>
>>> collect-result:
>>>
>>> BUILD FAILED
>>> /opt/src/River_Fixed/**peterConcurrentPolicy/build.**xml:2105: The
>>> following error occurred while executing this line:
>>> /opt/src/River_Fixed/**peterConcurrentPolicy/qa/**build.xml:357:
>>> condition satisfied
>>>
>>> Total time: 3 minutes 30 seconds
>>>
>>>
>>>     
>>
>>   
>
>


Mime
  • Unnamed multipart/mixed (inline, None, 0 bytes)
View raw message