no spans from hibernate

[dsvensson]

When enabling debug logging I can see output like this:

[dd.trace 2020-04-02 17:59:47:293 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Instrumentation muzzled: [hibernate, hibernate-core] -- datadog.trace.instrumentation.hibernate.core.v3_3.SessionFactoryInstrumentation on sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:47:293 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - -- datadog.trace.instrumentation.hibernate.core.v3_3.AbstractHibernateInstrumentation$V3Advice:43 Missing class org.hibernate.classic.Validatable
[dd.trace 2020-04-02 17:59:47:293 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - -- datadog.trace.instrumentation.hibernate.core.v3_3.AbstractHibernateInstrumentation$V3Advice:44 Missing class org.hibernate.transaction.JBossTransactionManagerLookup
[dd.trace 2020-04-02 17:59:47:293 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: hibernate -- datadog.trace.instrumentation.hibernate.core.v4_0.SessionFactoryInstrumentation on sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:47:294 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader sun.misc.Launcher$AppClassLoader@18b4aac2 -> [datadog.trace.instrumentation.hibernate.SessionMethodUtils, datadog.trace.instrumentation.hibernate.SessionState, datadog.trace.instrumentation.hibernate.HibernateDecorator, datadog.trace.instrumentation.hibernate.core.v4_0.AbstractHibernateInstrumentation$V4Advice]
[dd.trace 2020-04-02 17:59:47:294 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader <bootstrap> -> [datadog.trace.bootstrap.instrumentation.context.FieldBackedProvider$ContextAccessor$org$hibernate$SharedSessionContract$datadog$trace$instrumentation$hibernate$SessionState]
[dd.trace 2020-04-02 17:59:47:295 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader <bootstrap> -> [datadog.trace.bootstrap.instrumentation.context.FieldBackedProvider$ContextStore$org$hibernate$SharedSessionContract$datadog$trace$instrumentation$hibernate$SessionState]
[dd.trace 2020-04-02 17:59:47:305 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Found context-store access in datadog.trace.instrumentation.hibernate.core.v4_0.SessionFactoryInstrumentation
[dd.trace 2020-04-02 17:59:47:305 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_0.SessionFactoryInstrumentation: org.hibernate.SharedSessionContract -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:47:306 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Found context-store access in datadog.trace.instrumentation.hibernate.core.v4_0.SessionFactoryInstrumentation
[dd.trace 2020-04-02 17:59:47:306 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_0.SessionFactoryInstrumentation: org.hibernate.SharedSessionContract -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:47:307 +0200] [main] DEBUG datadog.trace.agent.tooling.AgentInstaller$TransformLoggingListener - Transformed org.hibernate.internal.SessionFactoryImpl -- sun.misc.Launcher$AppClassLoader@18b4aac2
....
[dd.trace 2020-04-02 17:59:48:892 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_3.SessionInstrumentation: org.hibernate.procedure.ProcedureCall -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:48:893 +0200] [main] DEBUG datadog.trace.agent.tooling.AgentInstaller$TransformLoggingListener - Transformed org.hibernate.internal.AbstractSharedSessionContract -- sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:48:952 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Instrumentation muzzled: [hibernate, hibernate-core] -- datadog.trace.instrumentation.hibernate.core.v3_3.QueryInstrumentation on sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:48:952 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - -- datadog.trace.instrumentation.hibernate.core.v3_3.AbstractHibernateInstrumentation$V3Advice:43 Missing class org.hibernate.classic.Validatable
[dd.trace 2020-04-02 17:59:48:952 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - -- datadog.trace.instrumentation.hibernate.core.v3_3.AbstractHibernateInstrumentation$V3Advice:44 Missing class org.hibernate.transaction.JBossTransactionManagerLookup
[dd.trace 2020-04-02 17:59:48:953 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: hibernate -- datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation on sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:48:954 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader <bootstrap> -> [datadog.trace.bootstrap.instrumentation.context.FieldBackedProvider$ContextAccessor$org$hibernate$Query$datadog$trace$instrumentation$hibernate$SessionState]
[dd.trace 2020-04-02 17:59:48:955 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader <bootstrap> -> [datadog.trace.bootstrap.instrumentation.context.FieldBackedProvider$ContextStore$org$hibernate$Query$datadog$trace$instrumentation$hibernate$SessionState]
[dd.trace 2020-04-02 17:59:48:956 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader sun.misc.Launcher$AppClassLoader@18b4aac2 -> [datadog.trace.instrumentation.hibernate.SessionMethodUtils, datadog.trace.instrumentation.hibernate.SessionState, datadog.trace.instrumentation.hibernate.HibernateDecorator, datadog.trace.instrumentation.hibernate.core.v4_0.AbstractHibernateInstrumentation$V4Advice]
[dd.trace 2020-04-02 17:59:48:956 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader <bootstrap> -> [datadog.trace.bootstrap.instrumentation.context.FieldBackedProvider$ContextAccessor$org$hibernate$Query$datadog$trace$instrumentation$hibernate$SessionState]
[dd.trace 2020-04-02 17:59:48:957 +0200] [main] DEBUG datadog.trace.agent.tooling.HelperInjector - Injecting classes onto classloader <bootstrap> -> [datadog.trace.bootstrap.instrumentation.context.FieldBackedProvider$ContextStore$org$hibernate$Query$datadog$trace$instrumentation$hibernate$SessionState]
[dd.trace 2020-04-02 17:59:48:989 +0200] [main] DEBUG datadog.trace.agent.tooling.AgentInstaller$TransformLoggingListener - Transformed org.hibernate.query.internal.QueryImpl -- sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:48:995 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Instrumentation muzzled: [hibernate, hibernate-core] -- datadog.trace.instrumentation.hibernate.core.v3_3.QueryInstrumentation on sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:48:995 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - -- datadog.trace.instrumentation.hibernate.core.v3_3.AbstractHibernateInstrumentation$V3Advice:43 Missing class org.hibernate.classic.Validatable
[dd.trace 2020-04-02 17:59:48:995 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - -- datadog.trace.instrumentation.hibernate.core.v3_3.AbstractHibernateInstrumentation$V3Advice:44 Missing class org.hibernate.transaction.JBossTransactionManagerLookup
[dd.trace 2020-04-02 17:59:48:996 +0200] [main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: hibernate -- datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation on sun.misc.Launcher$AppClassLoader@18b4aac2
[dd.trace 2020-04-02 17:59:49:029 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Found context-store access in datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation
[dd.trace 2020-04-02 17:59:49:029 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation: org.hibernate.Query -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:49:029 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Found context-store access in datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation
[dd.trace 2020-04-02 17:59:49:029 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation: org.hibernate.Query -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:49:029 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Found context-store access in datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation
[dd.trace 2020-04-02 17:59:49:029 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation: org.hibernate.Query -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:49:030 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Found context-store access in datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation
[dd.trace 2020-04-02 17:59:49:030 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation: org.hibernate.Query -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:49:030 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Found context-store access in datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation
[dd.trace 2020-04-02 17:59:49:030 +0200] [main] DEBUG datadog.trace.agent.tooling.context.FieldBackedProvider - Rewriting context-store map fetch for instrumenter datadog.trace.instrumentation.hibernate.core.v4_0.QueryInstrumentation: org.hibernate.Query -> datadog.trace.instrumentation.hibernate.SessionState
[dd.trace 2020-04-02 17:59:49:032 +0200] [main] DEBUG datadog.trace.agent.tooling.AgentInstaller$TransformLoggingListener - Transformed org.hibernate.query.internal.AbstractProducedQuery -- sun.misc.Launcher$AppClassLoader@18b4aac2

...so it seems to be doing something. But in the DataDog web interface I don't see any hibernate spans anywhere. Maybe my expectations of the hibernate integration are not aligned with reality, but as it's only mentioned as supported, without any example of how to set it up I can only imagine what it's supposed to do, which is, adding a span, maybe with some JPA name, with lots of postgres queries under it.

[randomanderson]

Looking at the tests, hibernate should be generating spans with the following operation names:

• hibernate.session
• hibernate.transaction.commit
• hibernate.criteria.list
• hibernate.criteria.uniqueresult
• hibernate.criteria.scroll
• hibernate.iterate
• hibernate.query.list
• hibernate.query.executeUpdate
• hibernate.query.uniqueResult
• hibernate.query.scroll
• hibernate.lock
• hibernate.refresh
• hibernate.get
• hibernate.insert
• hibernate.update
• hibernate.delete

depending on what you are doing. Are you seeing database spans from postgress? In the logs, do you see the spans being created? What frameworks are you using?

It may be easier to go through support@datadoghq.com . They can look at your exact traces as well as having better mechanisms for sharing logs and personal information

[dsvensson]

Yes. Database spans from Postgres works fine, but I was hoping the Hibernate support would somehow group them together or indicate involved JPAs, but perhaps that's not how it should work? Using Hibernate 5.4.11. There are no mentions of hibernate under "Tags" in the web interface.

As for logs, my logs do contain span_id which I use to get data presented under APM in the web interface.

[randomanderson]

I think your best bet is to go through support. It's difficult to diagnose issues like this without seeing your exact traces

[dsvensson]

That's the thing. There are no traces of hibernate to look at :) but sure, I'll give that a try.

[theigl]

@randomanderson: What there a resolution for this? I'm also not seeing Hibernate spans and don't want to contact support if there is an easy solution.

[randomanderson]

@theigl No. It's not something that can be diagnosed easily from a github issue.

What version of hibernate are you running? What application or server framework? What version of the tracer? Are you seeing database spans? Are you using JPA or another layer like Spring Repository? Do you have a minimal application that you can share?

[theigl]

@randomanderson:

What version of hibernate are you running? What application or server framework? What version of the tracer?

• Hibernate 5.4.16
• Spring Boot 2.3.0 with embedded Tomcat
• Tracer 0.50.0

Are you seeing database spans?

Yes. JDBC MySQL spans work as expected.

Are you using JPA or another layer like Spring Repository?

JPA via Spring's LocalContainerEntityManagerFactoryBean. DAOs use @Repository.

Do you have a minimal application that you can share?

Not at hand. I can try to extract something from my application but I'm not sure when I will be able to do that.

[gokhanoner]

@randomanderson any finding on this one? I also have same issue. I can see the hibernate generated SQL but no other traces!!