# Java agent TRACE log error

**URL:** <https://discuss.elastic.co/t/java-agent-trace-log-error/192688>\
**Category:** APM\
**Tags:** java\
**Created:** [July 29, 2019, 12:07pm UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688 "2019-07-29T12:07:03Z")\
**Posts on this page:** 18\
**Page:** 1

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [July 29, 2019, 12:07pm UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/1 "2019-07-29T12:07:04Z")

</div>

If you are asking about a problem you are experiencing, please use the following template, as it will help us help you. If you have a different problem, please delete all of this text 🙂

**Kibana version** :7.0.0

**Elasticsearch version** :7.0.0

**APM Server version** :7.2.0

**APM Agent language and version** :java elastic-apm-agent-1.7.0.jar

**Browser version** :

**Original install method (e.g. download page, yum, deb, from source, etc.) and version**:

**Fresh install or upgraded from other version?**

**Is there anything special in your setup?** For example, are you using the Logstash or Kafka outputs? Are you using a load balancer in front of the APM Servers? Have you changed index pattern, generated custom templates, changed agent configuration etc.

**Description of the problem including expected versus actual behavior. Please include screenshots (if relevant)**:  
setup:export CATALINA\_OPTS="$CATALINA\_OPTS -javaagent:/weblogic/elastic-apm-agent-1.7.0.jar"  
export CATALINA\_OPTS="$CATALINA\_OPTS -Delastic.apm.service\_name=rtrc-dsf"  
export CATALINA\_OPTS="$CATALINA\_OPTS -Delastic.apm.application\_packages=org.example,org.another.example"  
export CATALINA\_OPTS="$CATALINA\_OPTS -Delastic.apm.server\_urls=http://10.3.134.51:8200"  
export CATALINA\_OPTS="$CATALINA\_OPTS -Delastic.apm.log\_level=TRACE"

Tomcat version：apache-tomcat-7.0.70  
JDBC version:ojdbc6-11.2.0.4.jar

I want to captures DB querys,but only get this error.

**Steps to reproduce** :  
1.  
2.  
3.

**Errors in browser console (if relevant)**:  
2019-07-29 19:49:22.333 [apm-reporter] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'HttpServletDispatcher#doPost' 00-308309a92d6d599c0532c6e0730ac970-0ba844dd3daacccd-01 (c2a1fa9) (0)  
2019-07-29 19:49:22.333 [apm-reporter] TRACE co.elastic.apm.agent.impl.transaction.AbstractSpan - decrementing references at  
java.lang.RuntimeException: This is an expected exception. Is just used to record where the reference count has been decremented.  
at co.elastic.apm.agent.impl.transaction.AbstractSpan.decrementReferences(AbstractSpan.java:260)  
at co.elastic.apm.agent.impl.transaction.Transaction.decrementReferences(Transaction.java:224)  
at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.writeEvent(IntakeV2ReportingEventHandler.java:196)  
at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.handleEvent(IntakeV2ReportingEventHandler.java:171)  
at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.onEvent(IntakeV2ReportingEventHandler.java:146)  
at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.onEvent(IntakeV2ReportingEventHandler.java:64)  
at co.elastic.apm.agent.shaded.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)  
at co.elastic.apm.agent.shaded.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)  
at java.lang.Thread.run(Thread.java:745)

**Provide logs and/or server output (if relevant)**:

---

<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 29, 2019, 12:29pm UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/2 "2019-07-29T12:29:30Z")

</div>

As the message indicates, this is not an error but just logs the stacktrace of where reference count has been decremented.

> [@kin122](#):
>
> 2019-07-29 19:49:22.333 [apm-reporter] TRACE co.elastic.apm.agent.impl.transaction.AbstractSpan - decrementing references at  
> java.lang.RuntimeException: This is an expected exception. Is just used to record where the reference count has been decremented.

When setting `log_level` to `debug` or `info` the agent doesn't log that stack trace.

You would see the captured DB queries in Kibana, rather than in the logs. If that does not work, have a look at the [troubleshooting docs](https://www.elastic.co/guide/en/apm/agent/java/current/trouble-shooting.html).

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [July 30, 2019, 2:06am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/3 "2019-07-30T02:06:15Z")

</div>

tks，but there is no data about DB queries in Kibana.  
Its also no found in the troubleshooting docs .  
What should I do？

---

<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 30, 2019, 12:43pm UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/4 "2019-07-30T12:43:39Z")

</div>

As mentioned in the troubleshooting docs, could you please upload your debug logs? The logs should contain everything from the startup up until the first request has been executed.

Also please tell me a bit more how you are executing the DB queries. Are you using any frameworks or plain JDBC? Are the DB queries executed within a thread pool or within the request processing thread?

Thanks,  
Felix

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [July 31, 2019, 1:59am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/5 "2019-07-31T01:59:02Z")

</div>

hi @felixbarny ,  
I use mybatis to execute the DB queries. at the same time the DB queries are executed within a thread pool .  
Finally,i use trace\_methods get the DB queries as u told me in an other topic(thanks).  
settings like this:  
java -javaagent:/weblogic/app/etl-dsf/elastic-apm-agent-1.7.0.jar -Delastic.apm.service\_name=rtrc-dsf -Delastic.apm.server\_url=[http://10.3.134.51:8200](http://10.3.134.51:8200) -Delastic.apm.application\_packages= **-Delastic.apm.trace\_methods=cn.com.bsfit.frms.ums.etl.DsfETLTool#** \* -Delastic.apm.log\_level=DEBUG -Delastic.apm.log\_file=/weblogic/app/etl-dsf/logs/apm-trace.log -Djava.net.preferIPv4Stack=true -Xmx6144m -Xms6144m -jar xxxx.jar

but in normal setups,agent still cant get the transcation about DB queries.

This is the debug log with trace\_methods.

> 2019-07-31 08:35:56.168 [apm-server-healthcheck] DEBUG co.elastic.apm.agent.report.ApmServerHealthChecker - Starting healthcheck to [http://10.3.134.51:8200/](http://10.3.134.51:8200/)  
> 2019-07-31 08:35:56.188 [apm-server-healthcheck] INFO co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: { "build\_date": "2019-06-20T14:39:23Z", "build\_sha": "9a099b63c53eac8c55707df96193143ec66337e9", "version": "7.2.0"}  
> 2019-07-31 08:35:56.209 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - container ID is null  
> 2019-07-31 08:35:56.229 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.7.0 as rtrc-dsf on Java 1.7.0\_75 (Oracle Corporation) Linux 3.0.74-0.6.8-default  
> 2019-07-31 08:35:56.229 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - service\_name: 'rtrc-dsf' (source: Java System Properties)  
> 2019-07-31 08:35:56.230 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - trace\_methods: 'cn.com.bsfit.frms.ums.etl.DsfETLTool#\*' (source: Java System Properties)  
> 2019-07-31 08:35:56.230 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - server\_urls: '[http://10.3.134.51:8200](http://10.3.134.51:8200)' (source: Java System Properties)  
> 2019-07-31 08:35:56.230 [main] WARN co.elastic.apm.agent.configuration.StartupInfo - Detected usage of an old configuration key: 'server\_url'. Please use 'server\_urls' instead.  
> 2019-07-31 08:35:56.230 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - log\_level: 'DEBUG' (source: Java System Properties)  
> 2019-07-31 08:35:56.230 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - log\_file: '/weblogic/app/etl-dsf/logs/apm-trace.log' (source: Java System Properties)  
> 2019-07-31 08:35:56.230 [main] WARN co.elastic.apm.agent.configuration.StartupInfo - To enable all features and to increase startup times, please configure application\_packages  
> 2019-07-31 08:35:56.293 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying advice co.elastic.apm.agent.httpclient.ApacheHttpClientInstrumentation  
> 2019-07-31 08:35:56.301 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying advice co.elastic.apm.agent.httpclient.ApacheHttpAsyncClientInstrumentation  
> 2019-07-31 08:35:56.302 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying advice co.elastic.apm.agent.httpclient.ApacheHttpAsyncClientRedirectInstrumentation  
> 2019-07-31 08:35:56.303 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying advice co.elastic.apm.agent.plugin.api.ElasticApmApiInstrumentation$StartTransactionInstrumentation  
> 2019-07-31 08:35:56.303 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying advice co.elastic.apm.agent.plugin.api.ElasticApmApiInstrumentation$StartTransactionWithRemoteParentInstrumentation

Why? please

---

<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 31, 2019, 1:41pm UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/6 "2019-07-31T13:41:58Z")

</div>

> [@kin122](#):
>
> at the same time the DB queries are executed within a thread pool

The problem could be that we don't propagate the trace context to the thread pool which executes the DB queries. We have auto-instrumentation support for `java.util.concurrent.Executor` based thread pools. Which one are you using?

Again, it would help to see the full logs - from startup up until the first request has been executed.

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [August 1, 2019, 3:37am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/7 "2019-08-01T03:37:26Z")

</div>

> [@felixbarny](#):
>
> Again, it would help to see the full logs - from startup up until the first request has been executed.

hi @felixbarny ,we use `java.util.concurrent.Executor` in our programs. and i cant paste the full log.shall i message u?

`

---

<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:** [August 1, 2019, 7:58am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/8 "2019-08-01T07:58:06Z")

</div>

It's best to use a service like [https://gist.github.com](https://gist.github.com) to upload the logs 🙂

> [@kin122](#):
>
> we use `java.util.concurrent.Executor` in our programs

That's interesting. Do you know which Executor implementation you are using? Could you share the code how you set up the thread pool?

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [August 1, 2019, 9:39am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/9 "2019-08-01T09:39:06Z")

</div>

@felixbarny  
i share the log in this address,if u can get it(i didnt install git in my work computer).

> **[百度网盘-链接不存在](https://pan.baidu.com/s/1WiJG9NMF-mfO3Lv200_VYw)**
>
> 百度网盘为您提供文件的网络备份、同步和分享服务。空间大、速度快、安全稳固，支持教育网加速，支持手机端。注册使用百度网盘即可享受免费存储空间

and this is the code

> Blockquote  
> @Bean(destroyMethod = "shutdown")  
> public ThreadPoolExecutor mobPayBankThreadPool () {  
> ThreadPoolExecutor executor = (ThreadPoolExecutor) Executors  
> .newFixedThreadPool(mobSaveThreadSize);  
> return executor;  
> }

finally，im interested in why agent captured DBqureies when i used **trace\_methods**

---

<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:** [August 1, 2019, 11:47am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/10 "2019-08-01T11:47:12Z")

</div>

You don't need git to paste something on [gist.github.com](http://gist.github.com).

I don't speak Chinese but it seems I have to login in order to download the log. I'd prefer not having to create an account. You can also try [pastebin.com](http://pastebin.com), for example.

> [@kin122](#):
>
> im interested in why agent captured DBqureies when i used **trace\_methods**

The agent only records DB statements if there is an active transaction. It seems like the transaction's context is not properly propagated to the thread which executes the DB statements. When you utilize `trace_methods`, a new transaction will be created in the background thread.

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [August 2, 2019, 2:40am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/11 "2019-08-02T02:40:57Z")

</div>

got it  
this is the log  
[https://pastebin.com/5v87VPGx](https://pastebin.com/5v87VPGx)  
so,the agent wont get the DB queries in the threading pool by default?  
if i want to get it it must be `java.util.concurrent.Executor`and use more resources to utilize `trace_methods`.

---

<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:** [August 2, 2019, 8:18am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/12 "2019-08-02T08:18:11Z")

</div>

Taking the `DsfETLTool#write` transaction as an example, what's not working as expected?

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [August 2, 2019, 9:48am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/13 "2019-08-02T09:48:26Z")

</div>

its worked.  
i was confused why the agent wont get the DB queries in the threading pool by default.  
according to your answer, I understand now.  
thanks.😀😀  
by the way, will apm record the whole process by transactionID with just like pinpoint in the future ?

---

<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:** [August 2, 2019, 10:07am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/14 "2019-08-02T10:07:52Z")

</div>

> [@kin122](#):
>
> by the way, will apm record the whole process by transactionID with just like pinpoint in the future ?

What do you mean by that?

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [August 2, 2019, 11:24am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/15 "2019-08-02T11:24:05Z")

</div>

![](https://us1.discourse-cdn.com/elastic/original/3X/b/6/b6eec66a48d625969c5cf93c49486bb01b71b8a8.png)  
just like the picture shows  
will kibana show the whole transaction process with different nodes in a system?  
so we can track transactions for more operational information.

---

<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:** [August 2, 2019, 12:29pm UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/16 "2019-08-02T12:29:10Z")

</div>

Yes, that is how it would look like: [https://www.elastic.co/guide/en/apm/get-started/current/distributed-tracing.html](https://www.elastic.co/guide/en/apm/get-started/current/distributed-tracing.html)

---

<div class="post-metadata">

**Author:** ![kin122](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kin122/32/51521_2.png) [@kin122](https://discuss.elastic.co/u/kin122)\
**Post date:** [August 2, 2019, 12:47pm UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/17 "2019-08-02T12:47:22Z")

</div>

emmm，ok  
i was configured all java nodes with the agent in a system,but distributed tracing didnt work as the docs shows.  
maybe there is Nginx in the transaction.i will try remove then to test distributed tracing in next monday.  
@felixbarny  
Thank you for this several days to answer patiently

---

<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 23, 2019, 8:47am UTC](https://discuss.elastic.co/t/java-agent-trace-log-error/192688/18 "2019-08-23T08:47:24Z")

</div>

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