File.delete() pod MS Windows z YourKit Java Profiler 7.0 i ZipFileMonitor
Z Jacek Laskowski - Wiki Projektanta Java EE
Kto by pomyślał, że proste zadanie usunięcia pliku za pomocą java.io.File.delete() może mi zająć tyle czasu i ostateczny wynik będzie jedynie połowicznym sukcesem (przy braku sukcesów połowiczny sukces jest równie bezcenny jak ten pełen). Mógłbym nawet skłoniać się ku podsumowaniu, że było to typowe pyrrusowe zwycięstwo. Jest tyle artykułów dotyczących problemu usuwania plików za pomocą File.delete() pod MS Windows, że gdybym o tym wiedział z pewnością nie zabrałbym się za pisanie poprawki do zgłoszenia OPENEJB-746 Command line tool Deploy/Undeploy asymmetry.
Spis treści |
Dzień 1: Namierzanie problemu
Zaczęło się niewinnie. Ostatnie zgłoszenie, które blokowało wydanie OpenEJB 3.0-beta-2 i które tylko początkowo wydawało się być dziecinnie proste polegało na usuwania modułów EJB, EAR i WAR z Apache OpenEJB z jednoczesnym kasowaniem plików jar odpowiadającym im modułom. Postanowiłem je rozwiązać. Myślałem, że skoro sprowadza się to wyłącznie do usunięcia pliku to w zasadzie pracy jest na kilka minut. Jak się okazało zadanie zajęło mi ponad tydzień i rozwiązania finalnego jak nie ma, tak nie ma.
Problem można wyłuskać uruchamiając poniższy test jednostkowy.
@Test
public void testFileDeleteWithJarURLConnection() throws Exception {
File f = new File("Copy of openejb-javaagent-3.0.0-SNAPSHOT.jar");
URL url = new URL("jar:" + f.toURI().toString() + "!/");
JarFile jarFile = null;
JarURLConnection juc;
try {
juc = (JarURLConnection) url.openConnection();
jarFile = juc.getJarFile();
} finally {
if (jarFile != null) {
jarFile.close();
}
}
assert jarFile != null;
assert f.exists();
assert f.delete();
assert !f.exists();
}
Gdyby usunąć linię jarFile.close() wykonanie linii assert f.delete() zakończyłoby się wyjątkiem, co unaocznia problem. Tyle tylko, że faktycznie problem leży głębiej, w klasie java.net.URLClassLoader, która jest wręcz naszpikowana uzyciem java.net.JarURLConnection oraz java.util.jar.JarFile. Oczywiście w prostych, jednowątkowych aplikacjach, bądź, gdzie liczba zarządców klas jest niewielka problem łatwo wyizolować i poprawić. W przypadku OpenEJB takich miejsc jest...wystarczająco wiele, aby zająć mnie przez kilka dni.
Materiałem wprowadzającym mogłyby być następujące artykuły i zgłoszenia błędów w bazie błędów Java SDK.
- URL-downloaded jar files can consume all available file descriptors
- URL-downloaded jar files (jar_cache files) never get deleted
- Pitfalls of executing Java code from remote JAR files
- Tool for Diagnosing Failed GlassFish Redeployments/Undeployments on Windows due to Locked JARs
Kiedy poprosiłem o pomoc w rozwiązaniu problemu na grupie dev@openejb.apache.org - Re OPENEJB-746 Command line tool Deploy/Undeploy asymmetry, Dain wskazał mi na narzędzie YourKit Java Profiler, którego licencję mogłem pobrać z CodeHaus. Było to moje pierwsze użycie YourKit Java Profiler, więc pełen nadziei zabrałem się za jego rozpoznanie praktycznie.
Nie pisałem o tym wcześniej, ale coraz częściej korzystam z IntelliJ IDEA 7 jako środowisko pracy, a jako, że istnieje integracja pomiędzy obu narzędziami mogłem skorzystać z obu środowisk jednocześnie.
Dzień 2: Instalacja i integracja YourKit Java Profiler z IntelliJ IDEA
Rozpocząłem od instalacji YourKit Java Profiler (dalej YKP), co trwało przysłowiową chwilkę. Po instalacji przyszła pora na integrację obu środowisk - YKP oraz IDEA.
Najpierw wybór środowiska programistycznego
, gdzie istnieje możliwość wyboru katalogu z wtyczkami dla IDEI.
Ostatnie ostrzeżenie
i wtyczka zainstalowana!
Instalacja to po prostu przekopiowanie pliku jar do katalogu wtyczek IDEI.
Ktoś mógłby zapytać po co tyle zachodu z tą instalacją i integracją z IDEA, jednakże możliwość edycji plików w IDEA a śledzenie wykonywania programu w YourKit Java Profiler jest nie do przecenienia i w zasadzie nie wyobrażam sobie innej pracy z nimi.
Dzień 3 i kilka kolejnych: Profilowanie aplikacji
Uruchomienie aplikacji, którą można profilować z YourKit Java Profiler sprowadza się do uruchomienia wirtualnej maszyny Javy (JVM) z opcją -agentlib:yjpagent. JVM poszukuje agentów w ścieżce PATH, więc przed jego uruchomieniem konieczne było zmodyfikowanie zmiennej PATH o katalog YourKit Java Profiler.
jlaskowski@dev /cygdrive/c/oss/openejb3/assembly/openejb-standalone/target/openejb-3.0.0-SNAPSHOT $ export PATH="C:\Program Files\YourKit Java Profiler 7.0.9\bin\win32":$PATH
Mając tak przygotowane środowisko, do uruchomienia OpenEJB z profilerem wystarczyło następujące polecenie:
jlaskowski@dev /cygdrive/c/oss/openejb3/assembly/openejb-standalone/target/openejb-3.0.0-SNAPSHOT $ OPENEJB_OPTS="-agentlib:yjpagent" ./bin/openejb start [YourKit Java Profiler 7.0.9] Using JVMTI (1.5.0_14-b03;Sun Microsystems Inc.;mixed mode, sharing;Windows;32 bit JVM) [YourKit Java Profiler 7.0.9] Profiler agent is listening on port 10001... [YourKit Java Profiler 7.0.9] *** HINT ***: To get profiling results, connect to the application from the profiler UI Apache OpenEJB 3.0.0-SNAPSHOT build: 20080110-10:13 http://openejb.apache.org/ OpenEJB ready. [init] OpenEJB Remote Server ** Starting Services ** NAME IP PORT httpejbd 127.0.0.1 4204 telnet 127.0.0.1 4202 ejbd 127.0.0.1 4201 hsql 127.0.0.1 9001 admin thread 127.0.0.1 4200 ------- Ready!
Poprawne uruchomienie aplikacji oznaczane jest za pomocą komunikatów [YourKit Java Profiler 7.0.9].
Teraz wystarczy podłączyć się YourKit Java Profiler
i możemy rozpocząć profilowanie.
Mnie interesowała zajętość pamięci w trakcie działania programu, więc bez zbędnej straty czasu wybrałem zakładkę Memory
, gdzie mogłem na bieżąco monitorować zużycie pamięci i odkładane obiekty.
Można również monitorować pracę GC, ale to nie było w moim zainteresowaniu.
Problem z brakiem możliwości usuwania plików wiązał się z ich związaniem z działającą aplikacją i jej zarządcami klas, więc należało namierzyć miejsca "wycieku" plików i ich zamknięciu. Scenariusz testów polegał na zainstalowaniu modułu i jego deinstalacji, śledzenie zmian w pamięci i ponownie.
Najpierw zrzut po instalacji i odinstalowaniu modułu EJB.
z możliwością jednoczesnego otwarcia pliku do analizy.
Podczas wykonywania zrzutów pamięci w dzienniku zdarzeń OpenEJB pojawiały się następujące komunikaty:
[YourKit Java Profiler 7.0.9] Snapshot is saved to C:\Documents and Settings\jlaskowski\Snapshots\openejb_core_3.0.0_SNAPSHOT-2008-01-12.snapshot [YourKit Java Profiler 7.0.9] Snapshot is saved to C:\Documents and Settings\jlaskowski\Snapshots\openejb_core_3.0.0_SNAPSHOT-2008-01-12(1).snapshot [YourKit Java Profiler 7.0.9] Snapshot is saved to C:\Documents and Settings\jlaskowski\Snapshots\openejb_core_3.0.0_SNAPSHOT-2008-01-12(2).snapshot [YourKit Java Profiler 7.0.9] Snapshot is saved to C:\Documents and Settings\jlaskowski\Snapshots\openejb_core_3.0.0_SNAPSHOT-2008-01-12(3).snapshot [YourKit Java Profiler 7.0.9] Snapshot is saved to C:\Documents and Settings\jlaskowski\Snapshots\openejb_core_3.0.0_SNAPSHOT-2008-01-12(4).snapshot [YourKit Java Profiler 7.0.9] Snapshot is saved to C:\Documents and Settings\jlaskowski\Snapshots\openejb_core_3.0.0_SNAPSHOT-2008-01-12(5).snapshot
Najbardziej interesowało mnie użycie wszystkich obiektów typu ClassLoader.
Po drugim uruchomieniu scenariusza (instalacja i odinstalowanie modułu EJB) już było (prawie) jasne, dlaczego nie mogłem skasować pliku jar - pojawił się nowy zarządca klas - java.net.URLClassLoader.
Miałem możliwość analizy wszystkich utworzonych zarządców klas, aby upewnić się, że plik jar faktycznie należał do jednego z nich.
Mając dwa zrzuty pamięci mogłem je porównywać.
Wciąż możliwe było zawężenie wyniku do typowanych obiektów-winowajców.
Dla przypomnienia, ilość zarządców klas wzrosła o 1 podczas, gdy ilość modułów, którymi one zarządzają pozostała bez zmian. Scenariusz obejmował instalację i odinstalowanie modułu, a więc wszystkie struktury danych, które były powoływane podczas instalacji powinny być niszczone podczas jej deinstalacji.
Po kilku uruchomieniach i poprawkach doszedłem do następującej różnicy w obiektach przed i po scenariuszu testowym.
Podświetlony obiekt był winowajcą.
Konieczne należało podejrzeć wszystkie egzemplarze danego typu, aby przeanalizować ich zawartość (stan).
Jak mogłem się przekonać jeden z egzemplarzy URLJarFile był przechowywany przez statyczną klasę JarFileFactory. Oba typy są typami niepublicznymi, a dodatkowo specyficznymi dla Sun JVM.
Podobnie było z innymi obiektami pozostawionymi po poprzedniej instalacji modułu EJB, jak np. org.apache.openejb.core.security.jacc.BasicPolicyConfiguration.
Podgląd kodów źródłowych jest możliwy za pomocą menu kontekstowego Open Declaration in IDE Editor lub klawisza F7.
Inne spojrzenie na ten sam problem to zliczanie egzemplarzy typu URL.
co również wskazuje na JarFileFactory (!)
Dzień kolejny: Śledzenie wycieku z narzędziem ZipFileMonitor
Miałem już pewność, że całą winę za niemożność usunięcia plików jar ponosił JarFileFactory. Koniecznie należało usuwać odniesienia do plików jar przed ich usunięciem, aby wykonanie File.delete() zakończyło się poprawnie.
Próba znalezienia rozwiązania w całym gąszczu źródeł OpenEJB sprowadziła mnie na stronę Tool for Diagnosing Failed GlassFish Redeployments/Undeployments on Windows due to Locked JARs z narzędziem ZipFileMonitor, który pomocny był przy rozwiązywaniu podobnego problemu w....GlassFishu. Narzędzie za pomocą JDI monitoruje wykorzystanie egzamplarzy JarFile dla danego wzorca nazwy pliku.
Chwila na lekturę i po chwili miałem uruchomione kolejne narzędzie wspomagające mnie w trudach rozwiązania zgłoszenia.
Uruchomienie narzędzia ZipFileMonitor rozpoczyna się od uruchomienia śledzonego narzędzia z opcjami podobnymi do uruchomienia zdalnego debuggera (ech, może ma ktoś pomysł na przyjemniejszy odpowiednik po polsku?). Opcja server=y powoduje zatrzymanie procesu, aż do podłączenia się do niego procesu monitorującego.
jlaskowski@dev /cygdrive/c/oss/openejb3/assembly/openejb-standalone/target/openejb-3.0.0-SNAPSHOT $ OPENEJB_OPTS="-agentlib:jdwp=transport=dt_socket,server=y,address=5005" ./bin/openejb start Listening for transport dt_socket at address: 5005
Uruchomienie ZipFileMonitor to wykonanie polecenia:
C:\apps\cygwin\home\jlaskowski>java -classpath ZipFileMonitor.jar;c:/apps/java5/lib/tools.jar util.ZipFileMonitor -host localhost -port 5005 -filter ejb-ejb-2.1-SNAPSHOT
ZipFileMonitor(18-Mar-2007)
Can use instance filters: true
java.lang.NullPointerException
at util.ZipFileMonitor$JarFileClassInfo.getTargetConstructorLocation(ZipFileMonitor.java:454)
at util.ZipFileMonitor.addJarFileConstructorBreakpoint(ZipFileMonitor.java:284)
at util.ZipFileMonitor.setBreakpoints(ZipFileMonitor.java:271)
at util.ZipFileMonitor.run(ZipFileMonitor.java:100)
at util.ZipFileMonitor.main(ZipFileMonitor.java:75)
Pierwsze uruchomienie, podczas podłączania ZipFileMonitor z monitorowanym procesem zawsze kończy się z NPE, co na konsoli śledzonego procesu (OpenEJB) objawia się komunikatem błędu i rozpoczęciem pracy.
jlaskowski@dev /cygdrive/c/oss/openejb3/assembly/openejb-standalone/target/openejb-3.0.0-SNAPSHOT $ OPENEJB_OPTS="-agentlib:jdwp=transport=dt_socket,server=y,address=5005" ./bin/openejb start Listening for transport dt_socket at address: 5005 ERROR: transport error 202: recv error: Connection reset by peer ["transport.c",L41] Listening for transport dt_socket at address: 5005 Apache OpenEJB 3.0.0-SNAPSHOT build: 20080114-08:22 http://openejb.apache.org/ OpenEJB ready. [init] OpenEJB Remote Server ** Starting Services ** NAME IP PORT httpejbd 127.0.0.1 4204 telnet 127.0.0.1 4202 ejbd 127.0.0.1 4201 hsql 127.0.0.1 9001 admin thread 127.0.0.1 4200 ------- Ready!
Ponowne uruchomienie narzędzia ZipFileMonitor kończy się pomyślnie. Parametry uruchomieniowe odpowiadają parametrom śledzonego procesu. Dla mnie najważniejszą opcją była możliwość zawężenia ilości informacji o otwieranych plikach do tych, mnie interesujących - ejb-ejb-2.1-SNAPSHOT (parametr filter).
C:\apps\cygwin\home\jlaskowski>java -classpath ZipFileMonitor.jar;c:/apps/java5/lib/tools.jar util.ZipFileMonitor -host localhost -port 5005 -filter ejb-ejb-2.1-SNAPSHOT ZipFileMonitor(18-Mar-2007) Can use instance filters: true JarFile constructor bkpt req: breakpoint request java.util.jar.JarFile:134 (enabled) ZipFileClose bkpt req: breakpoint request java.util.zip.ZipFile:466 (enabled) Filter: [ejb-ejb-2.1-SNAPSHOT] ZipFileMonitorThread(18-Mar-2007) Ready to accept commands Monitor thread started >
Po wykonaniu scenariusza testowego, wydanie polecenia show wyświetla stan otwartych plików.
C:\apps\cygwin\home\jlaskowski>java -classpath ZipFileMonitor.jar;c:/apps/java5/lib/tools.jar util.ZipFileMonitor -host localhost -port 5005 -filter ejb-ejb-2.1-SNAPSHOT
ZipFileMonitor(18-Mar-2007)
Can use instance filters: true
JarFile constructor bkpt req: breakpoint request java.util.jar.JarFile:134 (enabled)
ZipFileClose bkpt req: breakpoint request java.util.zip.ZipFile:466 (enabled)
Filter: [ejb-ejb-2.1-SNAPSHOT]
ZipFileMonitorThread(18-Mar-2007)
Ready to accept commands
Monitor thread started
>Creating info for ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT.jar"
Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT.jar" with hash code 127
Close bkpt seen for h/c 127 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT.jar"
Removing previously-recorded ZipFile with hash code 127
...
show
Current list of opened but unclosed jar files matching the filter:
Path "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT.jar"
..Opened by hashCode object 155 from:
java.util.jar.JarFile.<init>(java\util\jar\JarFile.java:134)
java.util.jar.JarFile.<init>(java\util\jar\JarFile.java:70)
sun.misc.URLClassPath$JarLoader.getJarFile(sun\misc\URLClassPath.java:579)
sun.misc.URLClassPath$JarLoader.<init>(sun\misc\URLClassPath.java:546)
sun.misc.URLClassPath$3.run(sun\misc\URLClassPath.java:324)
java.security.AccessController.doPrivileged(java\security\AccessController.java:-1)
sun.misc.URLClassPath.getLoader(sun\misc\URLClassPath.java:313)
sun.misc.URLClassPath.getLoader(sun\misc\URLClassPath.java:290)
sun.misc.URLClassPath.findResource(sun\misc\URLClassPath.java:141)
java.net.URLClassLoader$2.run(java\net\URLClassLoader.java:362)
java.security.AccessController.doPrivileged(java\security\AccessController.java:-1)
java.net.URLClassLoader.findResource(java\net\URLClassLoader.java:359)
java.lang.ClassLoader.getResource(java\lang\ClassLoader.java:977)
org.apache.xbean.finder.ClassFinder.readClassDef(org\apache\xbean\finder\ClassFinder.java:697)
org.apache.xbean.finder.ClassFinder.<init>(org\apache\xbean\finder\ClassFinder.java:147)
org.apache.xbean.finder.ClassFinder.<init>(org\apache\xbean\finder\ClassFinder.java:112)
org.apache.openejb.config.DeploymentLoader.discoverModuleType(org\apache\openejb\config\DeploymentLoader.java:899)
org.apache.openejb.config.DeploymentLoader.load(org\apache\openejb\config\DeploymentLoader.java:85)
org.apache.openejb.assembler.DeployerEjb.deploy(org\apache\openejb\assembler\DeployerEjb.java:100)
org.apache.openejb.assembler.DeployerEjb.deploy(org\apache\openejb\assembler\DeployerEjb.java:80)
sun.reflect.NativeMethodAccessorImpl.invoke0(sun\reflect\NativeMethodAccessorImpl.java:-1)
sun.reflect.NativeMethodAccessorImpl.invoke(sun\reflect\NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(sun\reflect\DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(java\lang\reflect\Method.java:585)
org.apache.openejb.core.interceptor.ReflectionInvocationContext$Invocation.invoke(org\apache\openejb\core\interceptor\ReflectionInvocationContext.java:146)
org.apache.openejb.core.interceptor.ReflectionInvocationContext.proceed(org\apache\openejb\core\interceptor\ReflectionInvocationContext.java:129)
org.apache.openejb.core.interceptor.InterceptorStack.invoke(org\apache\openejb\core\interceptor\InterceptorStack.java:67)
org.apache.openejb.core.stateless.StatelessContainer._invoke(org\apache\openejb\core\stateless\StatelessContainer.java:210)
org.apache.openejb.core.stateless.StatelessContainer._invoke(org\apache\openejb\core\stateless\StatelessContainer.java:188)
org.apache.openejb.core.stateless.StatelessContainer.invoke(org\apache\openejb\core\stateless\StatelessContainer.java:165)
org.apache.openejb.server.ejbd.EjbRequestHandler.doEjbObject_BUSINESS_METHOD(org\apache\openejb\server\ejbd\EjbRequestHandler.java:214)
org.apache.openejb.server.ejbd.EjbRequestHandler.processRequest(org\apache\openejb\server\ejbd\EjbRequestHandler.java:121)
org.apache.openejb.server.ejbd.EjbDaemon.processEjbRequest(org\apache\openejb\server\ejbd\EjbDaemon.java:164)
org.apache.openejb.server.ejbd.EjbDaemon.service(org\apache\openejb\server\ejbd\EjbDaemon.java:122)
org.apache.openejb.server.ejbd.EjbDaemon.service(org\apache\openejb\server\ejbd\EjbDaemon.java:84)
org.apache.openejb.server.ejbd.EjbServer.service(org\apache\openejb\server\ejbd\EjbServer.java:60)
org.apache.openejb.server.ServiceLogger.service(org\apache\openejb\server\ServiceLogger.java:73)
org.apache.openejb.server.ServiceAccessController.service(org\apache\openejb\server\ServiceAccessController.java:55)
org.apache.openejb.server.ServiceDaemon$1.run(org\apache\openejb\server\ServiceDaemon.java:118)
java.lang.Thread.run(java\lang\Thread.java:595)
..Opened by hashCode object 224 from:
java.util.jar.JarFile.<init>(java\util\jar\JarFile.java:134)
java.util.jar.JarFile.<init>(java\util\jar\JarFile.java:70)
sun.misc.URLClassPath$JarLoader.getJarFile(sun\misc\URLClassPath.java:579)
sun.misc.URLClassPath$JarLoader.<init>(sun\misc\URLClassPath.java:546)
sun.misc.URLClassPath$3.run(sun\misc\URLClassPath.java:324)
java.security.AccessController.doPrivileged(java\security\AccessController.java:-1)
sun.misc.URLClassPath.getLoader(sun\misc\URLClassPath.java:313)
sun.misc.URLClassPath.getLoader(sun\misc\URLClassPath.java:290)
sun.misc.URLClassPath.getResource(sun\misc\URLClassPath.java:160)
java.net.URLClassLoader$1.run(java\net\URLClassLoader.java:192)
java.security.AccessController.doPrivileged(java\security\AccessController.java:-1)
java.net.URLClassLoader.findClass(java\net\URLClassLoader.java:188)
java.lang.ClassLoader.loadClass(java\lang\ClassLoader.java:306)
java.lang.ClassLoader.loadClass(java\lang\ClassLoader.java:251)
java.lang.ClassLoader.loadClassInternal(java\lang\ClassLoader.java:319)
java.lang.Class.forName0(java\lang\Class.java:-1)
java.lang.Class.forName(java\lang\Class.java:242)
org.apache.openejb.assembler.classic.EnterpriseBeanBuilder.load(org\apache\openejb\assembler\classic\EnterpriseBeanBuilder.java:366)
org.apache.openejb.assembler.classic.EnterpriseBeanBuilder.loadClass(org\apache\openejb\assembler\classic\EnterpriseBeanBuilder.java:346)
org.apache.openejb.assembler.classic.EnterpriseBeanBuilder.build(org\apache\openejb\assembler\classic\EnterpriseBeanBuilder.java:74)
org.apache.openejb.assembler.classic.EjbJarBuilder.build(org\apache\openejb\assembler\classic\EjbJarBuilder.java:52)
org.apache.openejb.assembler.classic.Assembler.createApplication(org\apache\openejb\assembler\classic\Assembler.java:485)
org.apache.openejb.assembler.classic.Assembler.createApplication(org\apache\openejb\assembler\classic\Assembler.java:414)
org.apache.openejb.assembler.DeployerEjb.deploy(org\apache\openejb\assembler\DeployerEjb.java:145)
org.apache.openejb.assembler.DeployerEjb.deploy(org\apache\openejb\assembler\DeployerEjb.java:80)
sun.reflect.NativeMethodAccessorImpl.invoke0(sun\reflect\NativeMethodAccessorImpl.java:-1)
sun.reflect.NativeMethodAccessorImpl.invoke(sun\reflect\NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(sun\reflect\DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(java\lang\reflect\Method.java:585)
org.apache.openejb.core.interceptor.ReflectionInvocationContext$Invocation.invoke(org\apache\openejb\core\interceptor\ReflectionInvocationContext.java:146)
org.apache.openejb.core.interceptor.ReflectionInvocationContext.proceed(org\apache\openejb\core\interceptor\ReflectionInvocationContext.java:129)
org.apache.openejb.core.interceptor.InterceptorStack.invoke(org\apache\openejb\core\interceptor\InterceptorStack.java:67)
org.apache.openejb.core.stateless.StatelessContainer._invoke(org\apache\openejb\core\stateless\StatelessContainer.java:210)
org.apache.openejb.core.stateless.StatelessContainer._invoke(org\apache\openejb\core\stateless\StatelessContainer.java:188)
org.apache.openejb.core.stateless.StatelessContainer.invoke(org\apache\openejb\core\stateless\StatelessContainer.java:165)
org.apache.openejb.server.ejbd.EjbRequestHandler.doEjbObject_BUSINESS_METHOD(org\apache\openejb\server\ejbd\EjbRequestHandler.java:214)
org.apache.openejb.server.ejbd.EjbRequestHandler.processRequest(org\apache\openejb\server\ejbd\EjbRequestHandler.java:121)
org.apache.openejb.server.ejbd.EjbDaemon.processEjbRequest(org\apache\openejb\server\ejbd\EjbDaemon.java:164)
org.apache.openejb.server.ejbd.EjbDaemon.service(org\apache\openejb\server\ejbd\EjbDaemon.java:122)
org.apache.openejb.server.ejbd.EjbDaemon.service(org\apache\openejb\server\ejbd\EjbDaemon.java:84)
org.apache.openejb.server.ejbd.EjbServer.service(org\apache\openejb\server\ejbd\EjbServer.java:60)
org.apache.openejb.server.ServiceLogger.service(org\apache\openejb\server\ServiceLogger.java:73)
org.apache.openejb.server.ServiceAccessController.service(org\apache\openejb\server\ServiceAccessController.java:55)
org.apache.openejb.server.ServiceDaemon$1.run(org\apache\openejb\server\ServiceDaemon.java:118)
java.lang.Thread.run(java\lang\Thread.java:595)
>exit
Done reading and processing commands
-- The application has disconnected --
Po wprowadzeniu użycia klasy org.apache.xbean.classloader.JarFileClassLoader z projektu Apache XBean rozwiązuje problem, gdyż klasa udostępnia możliwość czyszczenia wczytanych zasobów za pomocą metody destroy().
Kolejne uruchomienia wskazują na właściwą drogę rozwiązania problemu.
show
Current list of opened but unclosed jar files matching the filter:
Path "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT.jar"
..Opened by hashCode object 151 from:
java.util.jar.JarFile.<init>(java\util\jar\JarFile.java:134)
java.util.jar.JarFile.<init>(java\util\jar\JarFile.java:70)
sun.misc.URLClassPath$JarLoader.getJarFile(sun\misc\URLClassPath.java:579)
sun.misc.URLClassPath$JarLoader.<init>(sun\misc\URLClassPath.java:546)
sun.misc.URLClassPath$3.run(sun\misc\URLClassPath.java:324)
java.security.AccessController.doPrivileged(java\security\AccessController.java:-1)
sun.misc.URLClassPath.getLoader(sun\misc\URLClassPath.java:313)
sun.misc.URLClassPath.getLoader(sun\misc\URLClassPath.java:290)
sun.misc.URLClassPath.findResource(sun\misc\URLClassPath.java:141)
java.net.URLClassLoader$2.run(java\net\URLClassLoader.java:362)
java.security.AccessController.doPrivileged(java\security\AccessController.java:-1)
java.net.URLClassLoader.findResource(java\net\URLClassLoader.java:359)
java.lang.ClassLoader.getResource(java\lang\ClassLoader.java:977)
org.apache.xbean.finder.ClassFinder.readClassDef(org\apache\xbean\finder\ClassFinder.java:697)
org.apache.xbean.finder.ClassFinder.<init>(org\apache\xbean\finder\ClassFinder.java:147)
org.apache.xbean.finder.ClassFinder.<init>(org\apache\xbean\finder\ClassFinder.java:112)
org.apache.openejb.config.DeploymentLoader.discoverModuleType(org\apache\openejb\config\DeploymentLoader.java:898)
org.apache.openejb.config.DeploymentLoader.load(org\apache\openejb\config\DeploymentLoader.java:84)
org.apache.openejb.assembler.DeployerEjb.deploy(org\apache\openejb\assembler\DeployerEjb.java:100)
org.apache.openejb.assembler.DeployerEjb.deploy(org\apache\openejb\assembler\DeployerEjb.java:80)
sun.reflect.NativeMethodAccessorImpl.invoke0(sun\reflect\NativeMethodAccessorImpl.java:-1)
sun.reflect.NativeMethodAccessorImpl.invoke(sun\reflect\NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(sun\reflect\DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(java\lang\reflect\Method.java:585)
org.apache.openejb.core.interceptor.ReflectionInvocationContext$Invocation.invoke(org\apache\openejb\core\interceptor\ReflectionInvocationContext.java:146)
org.apache.openejb.core.interceptor.ReflectionInvocationContext.proceed(org\apache\openejb\core\interceptor\ReflectionInvocationContext.java:129)
org.apache.openejb.core.interceptor.InterceptorStack.invoke(org\apache\openejb\core\interceptor\InterceptorStack.java:67)
org.apache.openejb.core.stateless.StatelessContainer._invoke(org\apache\openejb\core\stateless\StatelessContainer.java:210)
org.apache.openejb.core.stateless.StatelessContainer._invoke(org\apache\openejb\core\stateless\StatelessContainer.java:188)
org.apache.openejb.core.stateless.StatelessContainer.invoke(org\apache\openejb\core\stateless\StatelessContainer.java:165)
org.apache.openejb.server.ejbd.EjbRequestHandler.doEjbObject_BUSINESS_METHOD(org\apache\openejb\server\ejbd\EjbRequestHandler.java:214)
org.apache.openejb.server.ejbd.EjbRequestHandler.processRequest(org\apache\openejb\server\ejbd\EjbRequestHandler.java:121)
org.apache.openejb.server.ejbd.EjbDaemon.processEjbRequest(org\apache\openejb\server\ejbd\EjbDaemon.java:164)
org.apache.openejb.server.ejbd.EjbDaemon.service(org\apache\openejb\server\ejbd\EjbDaemon.java:122)
org.apache.openejb.server.ejbd.EjbDaemon.service(org\apache\openejb\server\ejbd\EjbDaemon.java:84)
org.apache.openejb.server.ejbd.EjbServer.service(org\apache\openejb\server\ejbd\EjbServer.java:60)
org.apache.openejb.server.ServiceLogger.service(org\apache\openejb\server\ServiceLogger.java:73)
org.apache.openejb.server.ServiceAccessController.service(org\apache\openejb\server\ServiceAccessController.java:55)
org.apache.openejb.server.ServiceDaemon$1.run(org\apache\openejb\server\ServiceDaemon.java:118)
java.lang.Thread.run(java\lang\Thread.java:595)
Ostatecznie, wprowadzenie zmian polegających na zastąpieniu użycia URLClassLoader na odpowiednie wywołanie JarFileClassLoader oraz zamykanie go przy pomocy metody JarFileClassLoader.destroy() w momencie usuwania modułu z systemu zakończyło się pozytywnie. Żaden z plików modułu nie jest trzymany przez OpenEJB, a więc plik jar modułu można skasować pomyślnie za pomocą File.delete(). Hura!
C:\apps\cygwin\home\jlaskowski>java -classpath ZipFileMonitor.jar;c:/apps/java5/lib/tools.jar util.ZipFileMonitor -host localhost -port 5005 -filter ejb-ejb-2.1-SNAPSHOT ZipFileMonitor(18-Mar-2007) Can use instance filters: true JarFile constructor bkpt req: breakpoint request java.util.jar.JarFile:134 (enabled) ZipFileClose bkpt req: breakpoint request java.util.zip.ZipFile:466 (enabled) Filter: [ejb-ejb-2.1-SNAPSHOT] ZipFileMonitorThread(18-Mar-2007) Ready to accept commands Monitor thread started >Creating info for ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 121 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 139 Close bkpt seen for h/c 139 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 139 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 145 Close bkpt seen for h/c 145 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 145 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 147 Close bkpt seen for h/c 147 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 147 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 149 Close bkpt seen for h/c 149 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 149 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 152 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 154 Close bkpt seen for h/c 154 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 154 Close bkpt seen for h/c 154 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 149 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 147 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 145 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 139 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 152 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 152 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 164 Close bkpt seen for h/c 164 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 164 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 166 Close bkpt seen for h/c 166 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 166 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 168 Close bkpt seen for h/c 168 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 168 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 170 Close bkpt seen for h/c 170 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 170 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 176 Close bkpt seen for h/c 176 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 176 Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 180 Close bkpt seen for h/c 180 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 180 Close bkpt seen for h/c 180 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 176 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 170 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 168 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 166 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 164 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Close bkpt seen for h/c 121 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 121 Creating info for ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Adding new open of ZipFile "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" with hash code 204 Close bkpt seen for h/c 204 and file "C:\oss\openejb3\assembly\openejb-standalone\target\openejb-3.0.0-SNAPSHOT\apps\ejb-ejb-2.1-SNAPSHOT-2.jar" Removing previously-recorded ZipFile with hash code 204 show No unclosed jar files matching the filter >exit Done reading and processing commands -- The application has disconnected --
Podsumowanie
Po żmudnej analizie kodów źródłowych OpenEJB ostatecznie doszedłem do następującego stanu pamięci po wykonaniu scenariusza "Instalacja/Deinstalacja modułu".
To mogłoby wskazywać na rozwiązanie problemu, jednakże pojawił się nowy błąd, który najwyraźniej ujawnił się po naprawieniu, bądź tymczasowemu obejściu, problemu z JarFile. Nie mogę jeszcze odtrąbić sukcesu, ale zabawa z IntelliJ IDEA 7, YourKit Java Profiler 7.0 i ZipFileMonitor była przednia. Tylko tak dalej, a będę mógł zapomnieć o przyjemnościach spędzania weekendu inaczej niż przed monitorem komputera. Czego nikomu nie życzę!
