Your data. Anywhere you go.

New Relic for iOS or Android


Download on the App Store    Android App on Google play


New Relic Insights App for iOS


Download on the App Store


Learn more

Close icon

Unknown opcode while debugging async transactions not found

async

#1

Hi,
We are using Java APM agent for a complex service composed of several web services and REST APIs.
Some transactions are using async (CompletableFuture) requests and we can’t see them in newrelic UI.

Using some extra logs, I can see that some tokens are expiring but I’m not able to understand why.
You can see below a sample line with an opcode value I can’t decode.

FINER: Transaction com.newrelic.agent.Transaction@2ce7ba1d: Activity com.newrelic.agent.TransactionActivity@1 finished with opcode 176

Could you please give me the description of this code ?

BTW, we don’t want to instrument code, I can only add extra xml files inside Docker images hosting the services.

Thanks


#2

The opcode itself is covered on page 406 of https://cr.openjdk.java.net/~iris/se/11/latestSpec/java-se-11-jvms-draft-diffs.pdf

Are you able to share the line preceding and following that line? It might provide a bit more context.


#3

Hi,

Yes, please find more lines at the end of my comment.

For technical context, we are using IBM Websphere Liberty 19.0.0.9 with IBM JRE 8.0.5

Logs:
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINER: Transaction com.newrelic.agent.Transaction@2ce7ba1d: ignoring link call because transaction already on thread.
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINEST: Transaction com.newrelic.agent.Transaction@2ce7ba1d: created active token com.newrelic.agent.TokenImpl@7e00f2e9
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINER: Tracer (com.newrelic.agent.tracers.DefaultTracer@c0dcebf0) Started: java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(I)Ljava/util/concurrent/CompletableFuture;
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINER: Transaction com.newrelic.agent.Transaction@2ce7ba1d: ignoring link call because transaction already on thread.
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINEST: Suspend async
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINER: Transaction com.newrelic.agent.Transaction@2ce7ba1d is suspended
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINEST: Suspended async: com.ibm.ws.webcontainer31.async.AsyncContext31Impl@f177083b, for Transaction: com.newrelic.agent.Transaction@2ce7ba1d
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINEST: Request destroyed
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINEST: Transaction Activity com.newrelic.agent.TransactionActivity@0 marked as the response sender
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINEST: Distributed tracing enabled. Not adding response metadata
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINER: Tracer (com.newrelic.agent.tracers.DefaultTracer@94253cb2) Started: NR_RECORD_ASYNC_PROCESSING_CLASS.NR_RECORD_ASYNC_PROCESSING_METHOD()V
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINEST: TransactionActivity.clear()
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 158] com.newrelic FINE: Setting externalParameters to: com.newrelic.api.agent.HttpParameters@86bfaf26
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 158] com.newrelic FINE: Setting inboundResponseHeaders to: com.nr.agent.instrumentation.httpasyncclient4.InboundWrapper@effae18
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 158] com.newrelic FINEST: com.newrelic.agent.Transaction@2ce7ba1d–finish segment(): com.newrelic.agent.Segment@966e373c async finish with tracer com.newrelic.agent.tracers.OtherRootTracer@d63114a4
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 158] com.newrelic FINEST: tracerFinished: com.newrelic.agent.tracers.OtherRootTracer@d63114a4 opcode: 176 in transactionActivity com.newrelic.agent.TransactionActivity@1
restapi_1: Nov 18, 2019 13:24:39 +0000 [122 158] com.newrelic FINER: Transaction com.newrelic.agent.Transaction@2ce7ba1d: Activity com.newrelic.agent.TransactionActivity@1 finished with opcode 176


#4

BTW, I can also see some messages talking about “null”, if this can help to debug:
com.newrelic FINE: created com.newrelic.agent.TransactionActivity@7fffffff for null
com.newrelic FINER: activity com.newrelic.agent.TransactionActivity@9 starting


#5

When you see TransactionActivity@7fffffff it often means the agent traced a Transaction activity that turned out to be not related to a specific Transaction. It is fairly common and most of the time is not an issue.

One thing I often do when I’m running down a Transaction is to locate the ID, such as Transaction@2ce7ba1d, I grep the log for the ID to get an overview of the activity.

You can also see in the [] (square brackets] two integers. One is the pid and one is the tid. These can also be used to filter for specific activity.

Based on what I’m seeing from the logging you provided and the opcode 176, which is the result when a transaction is ignored or when it fails, I can see the reason behind one of them.

restapi_1: Nov 18, 2019 13:24:39 +0000 [122 1334] com.newrelic FINER: Transaction com.newrelic.agent.Transaction@2ce7ba1d: ignoring link call because transaction already on thread.

Async activity can lead to some unexpected behavior if the call goes outside of the visibility of the agent. I have frequently used an analogy of going on a blind date and your date excuses themselves to the restroom but is gone for an extraordinary amount of time. You are left wondering, not only if they are okay but should you wait for them because if they bolted out a back door or window and you don’t know it, you could be waiting for a very long time.
The design of the agent includes logic where it waits for a specific time before it discards an activity as well because if the agent waits until a response is given, the response time could be an outrageous value. If there is a great deal of async activity, the resources in Memory/CPU/Threads being held up in the waiting could possibly impact the application detrimentally.

Let us know if this information is helpful.


#6

Hi,
Thanks, we tried various ways but we are not able to see these transactions in newrelic dashboard.
It might be caused by our usage of Liberty server + JAX-RS VS basic servlet filters.
We are still trying some configuration updates but we don’t have a lot of time to debug this situation.
Thanks
Gael


#7

If you want to revisit this issue at a later time, let us know. We can always do the debugging/troubleshooting process through a ticket and come back to this thread with more of an answer when it’s resolved.