Java agent TRACE log error

Elastic Observability APM
1

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 :slight_smile:

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):

2

As the message indicates, this is not an error but just logs the stacktrace of where 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.

3

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

4

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

5

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 -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/
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' (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

6

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.

7

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

`

8

It's best to use a service like https://gist.github.com to upload the logs :slight_smile:

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

9

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

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

10

You don't need git to paste something on 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, for example.

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.

11

got it
this is the log
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.Executorand use more resources to utilize trace_methods.

12

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

13

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.:grinning::grinning:
by the way, will apm record the whole process by transactionID with just like pinpoint in the future ?

14

What do you mean by that?

15


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.

16

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

17

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

18

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