# Java APM agent sends no timeline spans

**URL:** <https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150>\
**Category:** APM\
**Created:** [July 23, 2018, 11:11am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150 "2018-07-23T11:11:15Z")\
**Posts on this page:** 11\
**Page:** 1

<div class="post-metadata">

**Author:** ![albert1625](https://avatars.discourse-cdn.com/v4/letter/a/d6d6ee/32.png) [@albert1625](https://discuss.elastic.co/u/albert1625)\
**Post date:** [July 23, 2018, 11:11am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/1 "2018-07-23T11:11:15Z")

</div>

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!

---

<div class="post-metadata">

**Author:** ![felixbarny](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/felixbarny/32/27341_2.png) [@felixbarny](https://discuss.elastic.co/u/felixbarny)\
**Post date:** [July 23, 2018, 12:13pm UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/2 "2018-07-23T12:13:08Z")

</div>

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](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)

---

<div class="post-metadata">

**Author:** ![albert1625](https://avatars.discourse-cdn.com/v4/letter/a/d6d6ee/32.png) [@albert1625](https://discuss.elastic.co/u/albert1625)\
**Post date:** [July 23, 2018, 12:46pm UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/3 "2018-07-23T12:46:58Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![felixbarny](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/felixbarny/32/27341_2.png) [@felixbarny](https://discuss.elastic.co/u/felixbarny)\
**Post date:** [July 24, 2018, 6:12am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/4 "2018-07-24T06:12:09Z")

</div>

Could you send me your [debug logs](https://www.elastic.co/guide/en/apm/agent/java/master/config-logging.html)?

---

<div class="post-metadata">

**Author:** ![albert1625](https://avatars.discourse-cdn.com/v4/letter/a/d6d6ee/32.png) [@albert1625](https://discuss.elastic.co/u/albert1625)\
**Post date:** [July 24, 2018, 8:21am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/5 "2018-07-24T08:21:26Z")

</div>

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=?
```

---

<div class="post-metadata">

**Author:** ![felixbarny](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/felixbarny/32/27341_2.png) [@felixbarny](https://discuss.elastic.co/u/felixbarny)\
**Post date:** [July 27, 2018, 8:30am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/6 "2018-07-27T08:30:41Z")

</div>

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?

```auto
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.

---

<div class="post-metadata">

**Author:** ![albert1625](https://avatars.discourse-cdn.com/v4/letter/a/d6d6ee/32.png) [@albert1625](https://discuss.elastic.co/u/albert1625)\
**Post date:** [July 27, 2018, 10:28am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/7 "2018-07-27T10:28:38Z")

</div>

> [@felixbarny](#):
>
> Are you referring the this log line?

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 ?

---

<div class="post-metadata">

**Author:** ![felixbarny](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/felixbarny/32/27341_2.png) [@felixbarny](https://discuss.elastic.co/u/felixbarny)\
**Post date:** [July 27, 2018, 11:20am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/8 "2018-07-27T11:20:00Z")

</div>

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

```auto
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

```auto
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.

---

<div class="post-metadata">

**Author:** ![albert1625](https://avatars.discourse-cdn.com/v4/letter/a/d6d6ee/32.png) [@albert1625](https://discuss.elastic.co/u/albert1625)\
**Post date:** [July 27, 2018, 12:22pm UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/9 "2018-07-27T12:22:55Z")

</div>

> [@felixbarny](#):
>
> 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_` )?

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

> [@felixbarny](#):
>
> Do you expect the other two SQL statements
> 
> ```auto
> 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?

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.

---

<div class="post-metadata">

**Author:** ![felixbarny](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/felixbarny/32/27341_2.png) [@felixbarny](https://discuss.elastic.co/u/felixbarny)\
**Post date:** [July 27, 2018, 1:03pm UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/10 "2018-07-27T13:03:33Z")

</div>

> [@albert1625](#):
>
> As soon as I disabled it everything started working as expected.

That's great to hear! 🎉

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

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [August 18, 2018, 1:08am UTC](https://discuss.elastic.co/t/java-apm-agent-sends-no-timeline-spans/141150/12 "2018-08-18T01:08:14Z")

</div>

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