Java APM agent sends no timeline spans

Elastic Observability APM
1

Hi everyone.

I am using ELK stack with running APM server and I have Spring Boot application which I used to run APM agent. There is no much logic behind application, but the main thing is that it has HTTP endpoints which runs queries to DB. When I'm trying to call endpoints agent sends data to APM server which sends it to Logstash, as a result i can see executed transactions in Kibana. The problem is that for some functions i can see transaction timeline (e.g. DB queries) and for other I can't when every function executed at least one DB query. As I can see in agent debug, it doesn't send any spans for these function which means that there is something wrong with agent, not APM server or ELK.

Maybe i missed some important configuration parameters ?

Thanks!

2

Could you try the latest snapshot form master? I think this problem might have already been fixed.

https://oss.sonatype.org/content/repositories/snapshots/co/elastic/apm/elastic-apm-agent/0.7.0-SNAPSHOT/elastic-apm-agent-0.7.0-20180723.093123-26.jar

3

Was using 0.6.0 agent before and just tried suggested one. Result is the same, no timelines.

4

Could you send me your debug logs?

5

Here are logs with 2 transactions where first one has spans and second doesn't:

2018-07-24 10:26:53.396 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - startTransaction '' d0f6a7c58c6b379793b16f7fefff4247 {
2018-07-24 10:26:53.435 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - startSpan '' d0f6a7c58c6b379793b16f7fefff4247:1 {
2018-07-24 10:26:53.436 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endSpan 'SET' d0f6a7c58c6b379793b16f7fefff4247:1
2018-07-24 10:26:53.503 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Type match for advice PreparedStatementInstrumentation: ((not(isInterface()) and name(contains(Statement))) and isSubTypeOf(interface java.sql.PreparedStatement)) matches class com.zaxxer.hikari.pool.HikariProxyPreparedStatement
2018-07-24 10:26:53.503 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Type match for advice StatementInstrumentation: ((not(isInterface()) and name(contains(Statement))) and isSubTypeOf(interface java.sql.Statement)) matches class com.zaxxer.hikari.pool.HikariProxyPreparedStatement
2018-07-24 10:26:53.512 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice StatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(hasTypes(with(0 matches erasure(is(class java.lang.String)))))) matches public java.sql.ResultSet com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(java.lang.String) throws java.sql.SQLException
2018-07-24 10:26:53.513 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice StatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(hasTypes(with(0 matches erasure(is(class java.lang.String)))))) matches public int com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(java.lang.String) throws java.sql.SQLException
2018-07-24 10:26:53.514 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice StatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(hasTypes(with(0 matches erasure(is(class java.lang.String)))))) matches public boolean com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(java.lang.String) throws java.sql.SQLException
2018-07-24 10:26:53.515 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice PreparedStatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(ofSize(0))) matches public int[] com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch() throws java.sql.SQLException
....
2018-07-24 10:26:53.525 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice PreparedStatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(ofSize(0))) matches public java.sql.ResultSet com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery() throws java.sql.SQLException
2018-07-24 10:26:53.525 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice PreparedStatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(ofSize(0))) matches public int com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate() throws java.sql.SQLException
2018-07-24 10:26:53.526 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice PreparedStatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(ofSize(0))) matches public boolean com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute() throws java.sql.SQLException
2018-07-24 10:26:53.526 [http-nio-8080-exec-5] DEBUG co.elastic.apm.bci.ElasticApmAgent - Method match for advice PreparedStatementInstrumentation: ((name(startsWith(execute)) and isPublic()) and hasParameter(ofSize(0))) matches public long com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeLargeUpdate() throws java.sql.SQLException
2018-07-24 10:26:53.530 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - startSpan '' d0f6a7c58c6b379793b16f7fefff4247:2 {
2018-07-24 10:26:53.533 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endSpan 'SELECT' d0f6a7c58c6b379793b16f7fefff4247:2
2018-07-24 10:26:53.556 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - startSpan '' d0f6a7c58c6b379793b16f7fefff4247:3 {
2018-07-24 10:26:53.557 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endSpan 'SET' d0f6a7c58c6b379793b16f7fefff4247:3
2018-07-24 10:26:53.568 [http-nio-8080-exec-5] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endTransaction 'MainApiController#getPersons' d0f6a7c58c6b379793b16f7fefff4247
2018-07-24 10:26:53.935 [apm-reporter] DEBUG co.elastic.apm.report.ApmServerHttpPayloadSender - Sending payload with 1 elements to APM server http://*****:8200
2018-07-24 10:26:53.941 [apm-reporter] DEBUG co.elastic.apm.report.ApmServerHttpPayloadSender - APM server responded with status code 202
2018-07-24 10:27:09.514 [http-nio-8080-exec-8] DEBUG co.elastic.apm.impl.ElasticApmTracer - startTransaction '' 570f5cb3c79de1b23df428b9ba801af5 {
2018-07-24 10:27:09.995 [http-nio-8080-exec-8] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endTransaction 'MainApiController#getPerson' 570f5cb3c79de1b23df428b9ba801af5
2018-07-24 10:27:10.935 [apm-reporter] DEBUG co.elastic.apm.report.ApmServerHttpPayloadSender - Sending payload with 1 elements to APM server http://*****:8200
2018-07-24 10:27:10.939 [apm-reporter] DEBUG co.elastic.apm.report.ApmServerHttpPayloadSender - APM server responded with status code 202

And these are Spring logs with executed SQL statements:

2018-07-24 10:26:53,499 DEBUG [org.hibernate.SQL] (http-nio-8080-exec-5) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_
2018-07-24 10:27:09,966 DEBUG [org.hibernate.SQL] (hystrix-MainApiController-1) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_ where persondb0_.id=?
2018-07-24 10:27:09,976 DEBUG [org.hibernate.SQL] (hystrix-MainApiController-1) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_ where persondb0_.id=?
6

Sorry for the long delay.

As I can see in agent debug, it doesn't send any spans for these function which means that there is something wrong with agent, not APM server or ELK.

Are you referring the this log line?

Sending payload with 1 elements to APM server http://*****:8200

This is expected even if the has spans, because in the current API, spans is a nested array within transaction.

Are you executing your DB statements in a different thread or are you using something like @Async? In that case, the spans currently can't be correlated to the transaction.

Could you try to enable the TRACE log level? You will then be able to see the actual JSON which is sent to the apm server.

7

Not really. First transaction has startTransaction and then some nested startSpan-endSpan blocks as you described it and then endTransaction, while second has only one startTransaction-endTransaction without any spans inside. TRACE log showed that same result - no nested spans in second transaction.

I haven't used @Async explicitly anywhere in project, but I'm not sure if something is running in multi-threading by default. I'm not really good at Java and I can't figure it out how to identify which thread was used to execute statements. Is there a way how to find it out ?

8

Actually, the SQL logs seem to indicate that there is something going on in multiple threads:

2018-07-24 10:26:53,499 DEBUG [org.hibernate.SQL] (http-nio-8080-exec-5) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_
2018-07-24 10:27:09,966 DEBUG [org.hibernate.SQL] (hystrix-MainApiController-1) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_ where persondb0_.id=?
2018-07-24 10:27:09,976 DEBUG [org.hibernate.SQL] (hystrix-MainApiController-1) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_ where persondb0_.id=?

The logs mention two different thread names: http-nio-8080-exec-5 and hystrix-MainApiController-1.

We do have plans to support context propagation for ExecutorService (Java thread pools). But I'm not sure if that would help in your case. I'd need to know more about how your application works and how it makes use of the thread pools.

It's about the MainApiController#getPerson transaction, right?

In the Spring logs, I can only see three SQL statements. The first transaction has one SELECT span. Is that the first SQL statement (select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_)?

Do you expect the other two SQL statements

2018-07-24 10:27:09,966 DEBUG [org.hibernate.SQL] (hystrix-MainApiController-1) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_ where persondb0_.id=?
2018-07-24 10:27:09,976 DEBUG [org.hibernate.SQL] (hystrix-MainApiController-1) select persondb0_.id as id1_0_, persondb0_.age as age2_0_, persondb0_.first_name as first_na3_0_, persondb0_.last_name as last_nam4_0_ from person persondb0_ where persondb0_.id=?

to be part of the other span?

Based on the tread names and timestamps, this seems to be the case.
Note the different thread names for start and stop of the second transaction (http-nio-8080-exec-8) and the one from the last two SQLs (hystrix-MainApiController-1).

Any insight on how the execution in the other thread takes place would be useful.

9

Yes, that's first transaction which appears in spans.

That's exactly what I expected.

What I discovered is that the reason of missing spans is Hystrix (fault tolerance library) and looks like it works asynchronously. I switched it on for some functions and spans was missing exactly for these functions. As soon as I disabled it everything started working as expected.

10

That's great to hear! :tada:

I'll keep Hystrix in mind when we add support for propagating context to thread pools.

12

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.