Fully featured low overhead profiler for Java EE and Java SE platforms.
Ultimate profiling and monitoring solution for Gradle, Maven, Ant, JUnit and TestNG.
Easy to use performance and memory profiler for .NET framework.

Bug: JDBC probe calls getMetadata() on a closed connection

Moderators: Vladimir Kondratyev, Anton Katilin

Bug: JDBC probe calls getMetadata() on a closed connection

Postby bcalmac » Mon May 02, 2016 9:37 pm

When I run my application with profiling enabled I get the exception below. You ca see the sequence Connection.close() -> YourKit -> Connection.getMetadata()

Code: Select all
2016-05-02 14:26:47.092 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
   at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
   at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
   at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
   at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
   at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]


The version I have is 2016.02-b35.
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby Anton Katilin » Mon May 02, 2016 9:57 pm

Hi,

This is a new issue. It must be H2 specific. Could you please provide the profiler agent log file ~/.yjp/log/<session name>-<pid>.log

Anyway, since we likely understand how to fix this problem, we can offer you the agent with a fix for testing. On which platform (OS, bitness) do you run the profiled application?

Best regards,
Anton
Anton Katilin
 
Posts: 5576
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby bcalmac » Tue May 03, 2016 1:32 am

I use Windows x64.

I'll include a few YJP logs in individual messages.
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby bcalmac » Tue May 03, 2016 1:36 am

It looks like posting is throttled. Here's one of the logs:


Code: Select all
16.02-35 0.016: Command line:
  C:\tools\yjp\jre64\bin\javaw.exe
  -XX:+HeapDumpOnOutOfMemoryError
  -Xmx4G
  -XX:PermSize=256m
  -XX:MaxPermSize=256m
  -jar
  ..\lib\yjp.jar
16.02-35 0.016: Executable: C:\tools\yjp\jre64\bin\javaw.exe
16.02-35 0.016: Windows 7; version 6.1.7601; 64-bit process
16.02-35 0.017: hid: 16022D45VV245481W6916ZW0VX03V680992XY094YU 64-bit machine
16.02-35 0.017: Today is 20160502
16.02-35 0.017: full_build_stamp: 2016.02.35 201604221705
16.02-35 0.017: Agent library path: C:\tools\yjp\bin\win64\yjpagent.dll
16.02-35 0.017:
---------------------------------------------------------------------
Product: YourKit Java Profiler 2016.02-b35 - built on 201604221705
JDK: 1.8.0_77
VM: Java HotSpot(TM) 64-Bit Server VM
Vendor: Oracle Corporation
OS: Windows 7
OS version: 6.1
OS arch: amd64
Date and time: Mon May 02 12:53:12 PDT 2016
Properties:
  awt.toolkit=sun.awt.windows.WToolkit
  file.encoding.pkg=sun.io
  file.encoding=Cp1252
  file.separator=\
  java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment
  java.awt.printerjob=sun.awt.windows.WPrinterJob
  java.class.path=..\lib\yjp.jar
  java.class.version=52.0
  java.endorsed.dirs=C:\tools\yjp\jre64\lib\endorsed
  java.ext.dirs=C:\tools\yjp\jre64\lib\ext;C:\Windows\Sun\Java\lib\ext
  java.home=C:\tools\yjp\jre64
  java.io.tmpdir=C:\Users\bca\AppData\Local\Temp\
  java.library.path=C:\tools\yjp\jre64\bin;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\tools\java\bin;C:\tools\scala\bin;C:\tools\maven\bin;C:\tools\ant\bin;C:\tools\gradle\bin;C:\tools\mariadb\bin;C:\tools\rabbitmq\rabbitmq_server-3.6.1\sbin;C:\tools\spring-boot-cli\bin;C:\tools\ruby\bin;C:\tools\sencha;C:\tools\bin;C:\tools\sysinternals;C:\cygwin\bin;C:\src\scripts;C:\Program Files\SourceGear\Common\DiffMerge;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\tools\idea\bin;C:\Program Files (x86)\Notepad++;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;.
  java.runtime.name=Java(TM) SE Runtime Environment
  java.runtime.version=1.8.0_77-b03
  java.specification.name=Java Platform API Specification
  java.specification.vendor=Oracle Corporation
  java.specification.version=1.8
  java.vendor.url.bug=http://bugreport.sun.com/bugreport/
  java.vendor.url=http://java.oracle.com/
  java.vendor=Oracle Corporation
  java.version=1.8.0_77
  java.vm.info=mixed mode
  java.vm.name=Java HotSpot(TM) 64-Bit Server VM
  java.vm.specification.name=Java Virtual Machine Specification
  java.vm.specification.vendor=Oracle Corporation
  java.vm.specification.version=1.8
  java.vm.vendor=Oracle Corporation
  java.vm.version=25.77-b03
  line.separator=


  os.arch=amd64
  os.name=Windows 7
  os.version=6.1
  path.separator=;
  sun.arch.data.model=64
  sun.awt.enableExtraMouseButtons=true
  sun.boot.class.path=C:\tools\yjp\jre64\lib\resources.jar;C:\tools\yjp\jre64\lib\rt.jar;C:\tools\yjp\jre64\lib\sunrsasign.jar;C:\tools\yjp\jre64\lib\jsse.jar;C:\tools\yjp\jre64\lib\jce.jar;C:\tools\yjp\jre64\lib\charsets.jar;C:\tools\yjp\jre64\lib\jfr.jar;C:\tools\yjp\jre64\classes
  sun.boot.library.path=C:\tools\yjp\jre64\bin
  sun.cpu.endian=little
  sun.cpu.isalist=amd64
  sun.desktop=windows
  sun.io.unicode.encoding=UnicodeLittle
  sun.java.command=..\lib\yjp.jar
  sun.java.launcher=SUN_STANDARD
  sun.jnu.encoding=Cp1252
  sun.management.compiler=HotSpot 64-Bit Tiered Compilers
  sun.os.patch.level=Service Pack 1
  user.country=US
  user.dir=C:\tools\yjp\bin
  user.home=C:\Users\bca
  user.language=en
  user.name=bca
  user.script=
  user.timezone=America/Los_Angeles
  user.variant=
Environment:
  ALLUSERSPROFILE=C:\ProgramData
  ANT_HOME=C:\tools\ant
  APPDATA=C:\Users\bca\AppData\Roaming
  CATALINA_HOME=C:\src\sz-80\tomcat
  COMMPath=C:\Program Files\Lenovo\Communications Utility
  COMPUTERNAME=CAS-BCA-W540
  ComSpec=C:\Windows\system32\cmd.exe
  CommonProgramFiles(x86)=C:\Program Files (x86)\Common Files
  CommonProgramFiles=C:\Program Files\Common Files
  CommonProgramW6432=C:\Program Files\Common Files
  ERLANG_HOME=c:\tools\erlang-18.3
  FP_NO_HOST_CHECK=NO
  GRAPHVIZ_DOT=C:\tools\graphviz\bin\dot.exe
  HOMEDRIVE=C:
  HOMEPATH=\Users\bca
  IDEA_JDK_64=c:\tools\java-8
  JAVA_HOME=C:\tools\java
  LOCALAPPDATA=C:\Users\bca\AppData\Local
  LOGONSERVER=\\CAS-AD-DC-01P
  M2_HOME=C:\tools\maven
  NUMBER_OF_PROCESSORS=8
  OS=Windows_NT
  PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC
  PROCESSOR_ARCHITECTURE=AMD64
  PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 60 Stepping 3, GenuineIntel
  PROCESSOR_LEVEL=6
  PROCESSOR_REVISION=3c03
  PSModulePath=C:\Windows\system32\WindowsPowerShell\v1.0\Modules\
  PUBLIC=C:\Users\Public
  Path=C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\tools\java\bin;C:\tools\scala\bin;C:\tools\maven\bin;C:\tools\ant\bin;C:\tools\gradle\bin;C:\tools\mariadb\bin;C:\tools\rabbitmq\rabbitmq_server-3.6.1\sbin;C:\tools\spring-boot-cli\bin;C:\tools\ruby\bin;C:\tools\sencha;C:\tools\bin;C:\tools\sysinternals;C:\cygwin\bin;C:\src\scripts;C:\Program Files\SourceGear\Common\DiffMerge;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\tools\idea\bin;C:\Program Files (x86)\Notepad++;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\
  ProgramData=C:\ProgramData
  ProgramFiles(x86)=C:\Program Files (x86)
  ProgramFiles=C:\Program Files
  ProgramW6432=C:\Program Files
  RABBITMQ_HOME=C:\tools\rabbitmq\rabbitmq_server-3.6.1
  READYAPPS=C:\ProgramData\Lenovo\ReadyApps
  SCALA_HOME=C:\tools\scala
  SESSIONNAME=Console
  SystemDrive=C:
  SystemRoot=C:\Windows
  TEMP=C:\Users\bca\AppData\Local\Temp
  TMP=C:\Users\bca\AppData\Local\Temp
  TVT=C:\Program Files (x86)\Lenovo
  TVTCOMMON=C:\Program Files (x86)\Common Files\Lenovo
  UATDATA=C:\Windows\CCM\UATData\D9F8C395-CAB8-491d-B8AC-179A1FE1BE77
  UOIPME_REG_PATH=C:\Program Files\Intel Corporation\USB over IP
  USERDNSDOMAIN=PANDUIT.COM
  USERDOMAIN=PANDUIT
  USERNAME=bca
  USERPROFILE=C:\Users\bca
  windir=C:\Windows
  windows_tracing_flags=3
---------------------------------------------------------------------


16.02-35 0.017: com.yourkit.Main1: starting...
16.02-35 0.017: com.yourkit.Main1: number of args: 0
16.02-35 0.017: com.yourkit.Main1: offlineOptionSpecified = false
16.02-35 0.027: com.yourkit.i.c1: [update installer]: no update scheduled - nothing to do
16.02-35 0.078: com.yourkit.Main1: oomeDumperStatus: 1
16.02-35 0.148: com.yourkit.i.f.a.a: FYI: native (current) LAF font: javax.swing.plaf.FontUIResource[family=Tahoma,name=Tahoma,style=plain,size=11]
16.02-35 0.148: com.yourkit.i.f.a.a: FYI: metal font: javax.swing.plaf.FontUIResource[family=Dialog,name=Dialog,style=bold,size=12]
16.02-35 0.150: com.yourkit.i.f.a.a: general font: javax.swing.plaf.FontUIResource[family=Segoe UI,name=Segoe UI,style=plain,size=12]
16.02-35 0.150: com.yourkit.i.f.a.a: menu font: javax.swing.plaf.FontUIResource[family=Segoe UI,name=Segoe UI,style=plain,size=12]
16.02-35 0.443: com.yourkit.i.i.c.c: ParallelExecutor: pool size 8
16.02-35 0.520: shmem: Global\YOURKIT SHARE G: OK, isFirst=1
16.02-35 0.521: shmem: Local\YOURKIT SHARE L: OK, isFirst=1
16.02-35 0.524: shmem: Global\YOURKIT SHARE2 G: OK, isFirst=0
16.02-35 0.524: shmem: Local\YOURKIT SHARE2 L: OK, isFirst=1
16.02-35 0.530: shmem: Global\YOURKIT SHARE5 G: OK, isFirst=0
16.02-35 0.530: shmem: Local\YOURKIT SHARE5 L: OK, isFirst=1
16.02-35 0.720: com.yourkit.i.b6: marker: created C:\Users\bca\.yjp\.yjp_20071015_ui60834
16.02-35 1.067: com.yourkit.i.q: UPDATES_URL: https://www.yourkit.com/updates_yjp_2016_02.xml?build=2016.02.35
16.02-35 2.153: com.yourkit.k.g: LWS-update: code=200 text: payload=AM...   result=ok
16.02-35 18.023: com.yourkit.d.bc: exiting now...
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby Anton Katilin » Tue May 03, 2016 10:04 am

Could you please download this agent library file

https://www.yourkit.com/download/tmp/20 ... pagent.dll

...and write it over the existing agent which, according to the log, should be C:\tools\yjp\bin\win64\yjpagent.dll
Anton Katilin
 
Posts: 5576
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby bcalmac » Tue May 03, 2016 5:36 pm

The new build doesn't fix the problem. I still get the same exception when enabling the profiler (everything's fine without it).

Furthermore, this new build doesn't generate a logfile under .yjp/log.
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby bcalmac » Tue May 03, 2016 5:40 pm

Here's the stacktrace, in case you expect some change there:

Code: Select all
2016-05-03 10:30:10.784 PDT [main] ERROR h2database - logstore:jdbc[3] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
   at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
   at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
   at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
   at com.yourkit.probes.ResourceCounter.getResourceNameSafe(ResourceCounter.java:258) [na:na]
   at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
   at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby Anton Katilin » Tue May 03, 2016 7:09 pm

Thanks for testing.

Regarding the log file. It's absence is absolutely strange. Are you sure you're looking for .yjp/log in appropriate user home? Anyway, you can explicitly specify the log file location with the startup option "logdir":
https://www.yourkit.com/docs/java/help/ ... ptions.jsp

Regarding the exception itself. Where do you see that exception, in what log file? Even if it is thrown, it must not go beyond the probe's code in the new agent. In other words, It must not be an uncaught exception now.
Anton Katilin
 
Posts: 5576
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby Anton Katilin » Tue May 03, 2016 7:10 pm

By the way, please note the log you've send earlier is not the profiled application's log, but the profiler UI's log.
Anton Katilin
 
Posts: 5576
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby bcalmac » Tue May 03, 2016 7:25 pm

Oh, OK. It looks like the most recent log I have is from 2016.02.34.

Code: Select all
16.02-34 0.001: Command line:
  C:\src\ss-selene\middle\runtime\SynapDM\SynapDM.exe
16.02-34 0.001: Executable: C:\src\ss-selene\middle\runtime\SynapDM\SynapDM.exe
16.02-34 0.001: Windows 7; version 6.1.7601; 64-bit process
16.02-34 0.002: hid: 16022D45VV245481W6916ZW0VX03V680992XY094YU 64-bit machine
16.02-34 0.002: Today is 20160422
16.02-34 0.002: full_build_stamp: 2016.02.34 201604051221
16.02-34 0.002: Agent library path: C:\tools\yjp\bin\win64\yjpagent.dll
16.02-34 0.002: Agent_OnLoad: orig_options=dir=.
  full_options=dir=.
16.02-34 0.002: phase: 1
16.02-34 0.002: jvmtiVersion: 30010201
16.02-34 0.002: vendor: Oracle Corporation
16.02-34 0.002: version: 24.79-b02
16.02-34 0.002: info: mixed mode, sharing
16.02-34 0.002: isJava6: 0
16.02-34 0.003: session_id: 34893775676203 (1461363499,8124)
16.02-34 0.004: line_method: 1
16.02-34 0.011: Reusing existing jar file: C:\cygwin\tmp\yjp201604051221.jar
16.02-34 0.012: JVMTI 30010201; 24.79-b02; Oracle Corporation; mixed mode, sharing
16.02-34 0.099: Successfully registered probes: 26
  Registered: .AWTEvents
  Registered: .AgentLoadingSupport
  Registered: .AsyncChannels
  Registered: .Cassandra
  Registered: .CassandraLW
  Registered: .Databases
  Registered: .DatabasesLW
  Registered: .Files
  Registered: .FilesLW
  Registered: .HBase
  Registered: .HBaseLW
  Registered: .JNDI
  Registered: .JPA_DataNucleus
  Registered: .JPA_EclipseLink
  Registered: .JPA_Hibernate
  Registered: .JPA_OpenJPA
  Registered: .JUnitTests
  Registered: .MongoDB
  Registered: .MongoDBLW
  Registered: .Processes
  Registered: .Servlets
  Registered: .ServletsLW
  Registered: .Sockets
  Registered: .SocketsLW
  Registered: .TestNG
  Registered: .Threads


Would it be useful for you to run the same test on b34?
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby Anton Katilin » Tue May 03, 2016 7:41 pm

You may try running with b34, but we would prefer the log created with the latest build with the proposed fix.

Also, it seems you paste truncated logs. We need full logs. If you cannot share it here in the forum, please feel free to send the files attached to support@yourkit.com

Could you please answer this question:
Where do you see that exception, in what log file? Even if it is thrown, it must not go beyond the probe's code in the new agent. In other words, It must not be an uncaught exception now.
Anton Katilin
 
Posts: 5576
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby bcalmac » Tue May 03, 2016 8:22 pm

To make sure I run the right patch: The file that I downloaded has 2,750,976 bytes. The old file (build 35) that I renamed to yjpagent.old.dll has 2,748,416 bytes. Does this match your numbers?

See two samples of the exception below. The exception is logged by H2, so it may show up even if you catch it.

Code: Select all
2016-05-03 10:30:10.784 PDT [main] ERROR h2database - logstore:jdbc[3] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
   at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
   at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
   at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
   at com.yourkit.probes.ResourceCounter.getResourceNameSafe(ResourceCounter.java:258) [na:na]
   at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
   at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]
   at com.synapsense.logback.db.H2EventRepository.saveEvents(H2EventRepository.java:59) [dm-logging-6.8.0.jar:na]
   at com.synapsense.logback.LoggingEventStore.process(LoggingEventStore.java:60) [dm-logging-6.8.0.jar:na]
   at com.synapsense.eventflow.backup.PrimarySwitch.process(PrimarySwitch.java:44) [dm-utils-6.8.0.jar:na]
   at com.synapsense.eventflow.backup.BackupFlowSwitcher.process(BackupFlowSwitcher.java:30) [dm-utils-6.8.0.jar:na]
   at com.synapsense.logback.ESAppender.append(ESAppender.java:102) [dm-logging-6.8.0.jar:na]
   at com.synapsense.logback.ESAppender.append(ESAppender.java:30) [dm-logging-6.8.0.jar:na]
   at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) [logback-core-1.0.13.jar:na]
   at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) [logback-core-1.0.13.jar:na]
   at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) [logback-classic-1.0.13.jar:na]
   at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) [logback-classic-1.0.13.jar:na]
   at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) [logback-classic-1.0.13.jar:na]
   at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395) [logback-classic-1.0.13.jar:na]
   at ch.qos.logback.classic.Logger.log(Logger.java:787) [logback-classic-1.0.13.jar:na]
   at org.apache.log4j.Category.differentiatedLog(Category.java:186) [log4j-over-slf4j-1.7.5.jar:1.7.5]
   at org.apache.log4j.Category.info(Category.java:229) [log4j-over-slf4j-1.7.5.jar:1.7.5]
   at com.synapsense.plugin.simulator.SimulatorPlugin.loadConfFile(SimulatorPlugin.java:166) [dm-simulator-plugin-6.8.0.jar:na]
   at com.synapsense.plugin.simulator.SimulatorPlugin.<init>(SimulatorPlugin.java:50) [dm-simulator-plugin-6.8.0.jar:na]
   at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [na:1.7.0_79]
   at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [na:1.7.0_79]
   at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [na:1.7.0_79]
   at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [na:1.7.0_79]
   at java.lang.Class.newInstance(Class.java:379) [na:1.7.0_79]
   at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:373) [na:1.7.0_79]
   at java.util.ServiceLoader$1.next(ServiceLoader.java:445) [na:1.7.0_79]
   at com.synapsense.plugin.manager.DeviceManagerCore.loadPlugins(DeviceManagerCore.java:48) [dm-core-6.8.0.jar:na]
   at com.synapsense.plugin.manager.DeviceManagerCore.<init>(DeviceManagerCore.java:36) [dm-core-6.8.0.jar:na]
   at com.synapsense.plugin.manager.DeviceManagerCore.<clinit>(DeviceManagerCore.java:26) [dm-core-6.8.0.jar:na]
   at com.synapsense.plugin.Launcher.main(Launcher.java:51) [dm-core-6.8.0.jar:na]


Code: Select all
2016-05-03 10:30:18.773 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
   at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
   at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
   at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
   at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
   at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
   at com.yourkit.probes.ResourceCounter.getResourceNameSafe(ResourceCounter.java:258) [na:na]
   at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
   at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
   at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
   at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]
   at com.synapsense.plugin.transport.db.H2DataRepository.saveDataPoints(H2DataRepository.java:76) [dm-es-transport-6.8.0.jar:na]
   at com.synapsense.plugin.transport.jms.DataEventStore.process(DataEventStore.java:52) [dm-es-transport-6.8.0.jar:na]
   at com.synapsense.eventflow.backup.PrimarySwitch.process(PrimarySwitch.java:44) [dm-utils-6.8.0.jar:na]
   at com.synapsense.eventflow.backup.BackupFlowSwitcher.process(BackupFlowSwitcher.java:30) [dm-utils-6.8.0.jar:na]
   at com.synapsense.plugin.transport.jms.JMSTransport.sendData(JMSTransport.java:217) [dm-es-transport-6.8.0.jar:na]
   at com.synapsense.plugin.manager.CompositeTransport.sendData(CompositeTransport.java:104) [dm-core-6.8.0.jar:na]
   at com.synapsense.plugin.simulator.sensorplace.SensorsStore.sendValue(SensorsStore.java:120) [dm-simulator-plugin-6.8.0.jar:na]
   at com.synapsense.plugin.simulator.sensorplace.SensorImitator.run(SensorImitator.java:133) [dm-simulator-plugin-6.8.0.jar:na]
   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_79]
   at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) [na:1.7.0_79]
   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) [na:1.7.0_79]
   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.7.0_79]
   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_79]
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_79]
   at java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]


But something is still messed up. The behavior with the profiler enabled is different. H2 will keep trying to close that original connection on any later activity and fail every time. This is just a grep for the first line of the exception:

Code: Select all
   1854   2016-05-03 10:30:10.784 PDT [main] ERROR h2database - logstore:jdbc[3] exception
   1945   2016-05-03 10:30:11.760 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
   1979   2016-05-03 10:30:11.929 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
   2013   2016-05-03 10:30:12.218 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
   2064   2016-05-03 10:30:12.810 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
   2098   2016-05-03 10:30:13.410 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
   2145   2016-05-03 10:30:14.005 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
   2179   2016-05-03 10:30:14.900 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
   2213   2016-05-03 10:30:15.794 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
   2247   2016-05-03 10:30:16.986 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
   2281   2016-05-03 10:30:17.880 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
   2336   2016-05-03 10:30:18.773 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
   2370   2016-05-03 10:30:19.376 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
   2404   2016-05-03 10:30:19.966 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
   2438   2016-05-03 10:30:20.867 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
   2472   2016-05-03 10:30:22.052 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
   2506   2016-05-03 10:30:22.943 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
   2540   2016-05-03 10:30:23.839 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
   2574   2016-05-03 10:30:25.034 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
   2608   2016-05-03 10:30:25.918 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
   2642   2016-05-03 10:30:26.224 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
   2676   2016-05-03 10:30:26.819 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
   2710   2016-05-03 10:30:28.011 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
   2744   2016-05-03 10:30:28.310 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
   2778   2016-05-03 10:30:28.905 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
   2812   2016-05-03 10:30:29.205 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
   2846   2016-05-03 10:30:29.800 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
   2880   2016-05-03 10:30:30.695 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception


Instead of catching the exception, can you instead check that the connection is not already closed? This would make YJP more transparent. Who knows what funky stuff the H2 connection pool does when closing a connection? Maybe it also tries closing connections that failed earlier. All exception above refer to the same connection, identified as [90007-172].

Finally, why do I no longer see the yjp log files after the b35 upgrade? Can I look for them in some other place?
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby Anton Katilin » Tue May 03, 2016 8:58 pm

Yes, you were running the right patch.

The exception is logged by H2, so it may show up even if you catch it.

OK.

Instead of catching the exception, can you instead check that the connection is not already closed?

We've improved the fix according to this approach. Could you please try the latest agent:
https://www.yourkit.com/download/tmp/20 ... pagent.dll
The size should be 2,615,296.

Finally, why do I no longer see the yjp log files after the b35 upgrade? Can I look for them in some other place?

I don't know what happened. There were no changes between b34 and b35 in regard of the log file processing. We do not see any log file issues with the newest builds.

Perhaps something has changed on your system. For example, you use cygwin. If it redefines the user home variables used by Java, please take a look at cygwin's user home instead of the normal Windows user home (or vise versa).

Anyway, since you get the logs with "logdir" specified (you do, right?), the problem is not with the agent's inability to create the log but rather with the detected user home directory where it should be located.

If the agent cannot create the log, it writes an error message to stdout or stderr (sorry, don't remember the exact stream). Please check the application logs for such messages.
Anton Katilin
 
Posts: 5576
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby bcalmac » Wed May 04, 2016 12:25 am

Looks good now, thank you!

I'll track down the log problem some other time, now I'm anxious to get back to work.
bcalmac
 
Posts: 13
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Postby Anton Katilin » Wed May 04, 2016 8:14 am

Thank you for testing. The next build 36 will contain the fix.
Anton Katilin
 
Posts: 5576
Joined: Wed Aug 11, 2004 8:37 am

Next

Return to Java Profiler

Who is online

Users browsing this forum: Google [Bot] and 9 guests