Understanding the AppDynamics asynchronous (async) thread detection life cycle can help you to troubleshoot missing threads and related async metrics. Use agent log files to search for evidence of each phase of thread detection and reporting.
The phases in the thread detection process are described here: AppDynamics Auto Discovery Life Cycle.
Each step must complete successfully before the next step begins. When you are troubleshooting, verify that each step happened successfully.
Determining Successful Thread Detection and Reporting
Generate and retrieve the agent logs using Debug level. For details on how to do this, see Enable Debug Level Logging. You may need both the agent logs and the REST logs. If so, see Request Agent Log Files. Be sure to request the logs with logger level=debug.
When you search, it is efficient to search all files at the same time for the best results. Registration of the higher-level objects such as BTs, backends, and errors appear in the agent.log files. Metric registration and metric uploads appear in the REST log.
1. Async Thread Detection
For details on how AppDynamics handles multi-threaded transactions, see:
You can verify instrumentation in the agent and BCT log. For example, this shows instrumentation of the run() and init() methods for the CartAction$1 thread.
Agent Log showing instrumentation
agent.2013_08_01__20_05_55.0.log:[AD Thread Pool-Global1] 01 Aug 2013 20:12:31,083 INFO AClassTransformation - Re-transforming class [com.appdynamicspilot.action.CartAction$1] because of newly added rule [Runtime [interface=SM{ex_type=EQUALS, ex_pattern='java.lang.Runnable', type=EQUALS, pattern='java.lang.Runnable'}], Method [ method=SM{ex_type=EQUALS, ex_pattern='run', type=EQUALS, pattern='run'}] ]
agent.2013_08_01__20_05_55.0.log:[AD Thread Pool-Global1] 01 Aug 2013 20:12:31,443 INFO AClassTransformation - Re-transforming class [com.appdynamicspilot.action.CartAction$1] because of newly added rule [Runtime [interface=SM{ex_type=EQUALS, ex_pattern='java.lang.Runnable', type=EQUALS, pattern='java.lang.Runnable'}], Method [ method=SM{ex_type=EQUALS, ex_pattern='<init>', type=EQUALS, pattern='<init>'}] ]
BCT Log showing interceptor
Matching method <init> ((Lcom/appdynamicspilot/action/CartAction;ILcom/appdynamicspilot/jms/MessageProducer;Lcom/appdynamicspilot/service/CartService;)V)
Applying method interceptor async.handoffAsyncHandOffIdentificationTracker at com/appdynamicspilot/action/CartAction$1.<init> ((Lcom/appdynamicspilot/action/CartAction;ILcom/appdynamicspilot/jms/MessageProducer;Lcom/appdynamicspilot/service/CartService;)V) id:95
Matching method run (()V)
Applying method interceptor async.handoffAsyncHandOffExecutionTracker at com/appdynamicspilot/action/CartAction$1.run (()V) id:96
2. Confirm Thread Registration
When a thread is detected, the agent sends a registration request to the controller and the controller assigns an ID to the thread. The ID is used for communication between the agent and controller to identify exactly which objects are being reported and stored in the controller database.
You can find the thread registration log entries in the agent.log files. To confirm registration, look for the registration request and response entries and find the ID assigned to the thread.
To find thread registration request log entries, search the log files using the search string, "INFO AsyncCorrelationADDRepository - Sending ADDs to register". You should see entries similar to this:
Thread Registration Request
[AD Thread Pool-Global0] 03 Aug 2013 00:17:17,075 INFO AsyncCorrelationADDRepository - Sending ADDs to register [ApplicationDiagnosticData{key='CartAction$1', name=CartAction$1, diagnosticType=THREAD_TASK, configEntities=null, summary='CartAction$1'}]
The string between the brackets [] identifies the type of object (Application Diagnostic Data or ADD), and contains values for key, name, diagnosticType, and summary. In this case, the diagnosticType=THREAD_TASK, and the key=CartAction$1.
Using "CartAction$1" as the search string, you can find the log entry that contains the ID assigned to this error. In this case the ID is 75 as shown in here.
Thread Registration Response
[AD Thread Pool-Global0] 03 Aug 2013 00:17:07,054 INFO AsyncCorrelationADDRepository - Registered ADDs [{CartAction$1=75}]
Find thread registration response log entries
- Use search string = INFO AsyncCorrelationADDRepository - Registered ADDs
Use the more general search string "INFO AsyncCorrelationADDRepository - Registered ADDs" to find all the thread objects that were registered during the duration of your logging session.
If you do not see successful registration request and response, look in the Controller Logs for exceptions related to error registration.
3. Confirm Metric Registration
After successful registration, the agent keeps an map in memory with the ID, type, and name for each thread. The next time the thread is detected, the agent is ready to report metrics. A similar process of request and response between the agent and controller enables the controller to assign each metric an ID.
Find thread metric registration request log entries
- Use search string = Th:<thread-ID>
- Use the thread number identified in the previous step to find the metric registration requests and responses.
- Using the search string and substituting 75 for the thread ID (found in phase 2), gives search results similar to the following:
<metric time-rollup-type="AVERAGE" name="BTM|BTs|BT:132|Component:7|Th:75|Average Response Time (ms)"hole-fill-type="REGULAR_COUNTER" cluster-rollup-type="INDIVIDUAL"/>
<metric time-rollup-type="SUM" name="BTM|BTs|BT:132|Component:7|Th:75|Number of Very Slow Calls" hole-fill-type="REGULAR_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|BTs|BT:132|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Average Response Time (ms)" hole-fill-type="REGULAR_COUNTER" cluster-rollup-type="INDIVIDUAL"/>
<metric time-rollup-type="AVERAGE" name="BTM|BTs|BT:132|Component:7|Th:75|Errors per Minute" hole-fill-type="RATE_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|Application Summary|Component:7|Th:75|Calls per Minute" hole-fill-type="RATE_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|Application Summary|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Calls per Minute" hole-fill-type="RATE_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="SUM" name="BTM|BTs|BT:132|Component:7|Th:75|Number of Slow Calls" hole-fill-type="REGULAR_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|Application Summary|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Average Response Time (ms)" hole-fill-type="REGULAR_COUNTER" cluster-rollup-type="INDIVIDUAL"/>
<metric time-rollup-type="SUM" name="BTM|BTs|BT:132|Component:7|Th:75|Stall Count" hole-fill-type="REGULAR_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|BTs|BT:132|Component:7|Th:75|Calls per Minute" hole-fill-type="RATE_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|Application Summary|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Errors per Minute" hole-fill-type="RATE_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|BTs|BT:132|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Calls per Minute" hole-fill-type="RATE_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|BTs|BT:132|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Errors per Minute" hole-fill-type="RATE_COUNTER" cluster-rollup-type="COLLECTIVE"/>
<metric time-rollup-type="AVERAGE" name="BTM|BTs|BT:132|Component:7|Th:75|Normal Average Response Time (ms)" hole-fill-type="REGULAR_COUNTER" cluster-rollup-type="INDIVIDUAL"/>
Find thread registration response log entries
In the above search results, you can see both the metric registration request and the response. The entries beginning with "<metric id=" show the ID assigned to each separate error's metrics similar to this:
Line 1475: <metric id="2445" name="BTM|BTs|BT:132|Component:7|Th:75|Normal Average Response Time (ms)"/>
Line 1488: <metric id="2522" name="BTM|BTs|BT:132|Component:7|Th:75|Stall Count"/>
Line 1494: <metric id="2502" name="BTM|BTs|BT:132|Component:7|Th:75|Errors per Minute"/>
Line 1495: <metric id="2416" name="BTM|BTs|BT:132|Component:7|Th:75|Calls per Minute"/>
Line 1497: <metric id="2552" name="BTM|Application Summary|Component:7|Th:75|Calls per Minute"/>
Line 1522: <metric id="2529" name="BTM|BTs|BT:132|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Calls per Minute"/>
Line 1537: <metric id="2496" name="BTM|Application Summary|Component:7|Th:75|Exit Call:JMS|To:{[UNRESOLVED][13]}|Calls per Minute"/>
...
You can see the metric ID assigned to each metric for thread ID=75. Note the BT (business transaction) ID=132.
If you do not see successful request and response for the metric, look in the Controller Logs for exceptions related to error metric registration.
4. Thread Metrics Reporting
After successful metric registration, metrics are reported to the controller every minute. Using the metric ID, you can search the REST log for the metric upload.
Find thread metric upload log entries:
Use the metric ID that you found at prior step when you verified metric registration.
Look for log entries showing thread metric reporting uploads. This example shows some of the search results matching the metric ID values in the previous step:
<metric id='2445', value[sum=0, count=0, min=0, max=0, current=0]>
<metric id='2522', value[sum=0, count=1, min=0, max=0, current=0]>
<metric id='2502', value[sum=909, count=1, min=909, max=909, current=909]>
If you do not see successful metric data uploads, look in the Controller Logs for exceptions related to metric data upload.
Sample Logs
A zip file containing the log files used for this topic is attached.
