Call tree always empty #41

danielthegray · 2017-03-29T15:21:21Z

I am using StageMonitor version 0.31.0, and running an app on Tomcat 8.5.

I have the following configuration:

stagemonitor.profiler.active=true
stagemonitor.web.widget.enabled=true
stagemonitor.internal.monitoring=true
stagemonitor.elasticsearch.configurationSource.deactivateStagemonitorIfEsIsDown=false
stagemonitor.applicationName=myApp
stagemonitor.profiler.logCallStacks=true
stagemonitor.instrument.include=
stagemonitor.instrument.excludeContaining=
stagemonitor.requestmonitor.cpuTime=true
stagemonitor.profiler.minExecutionTimeNanos=500

I've been toying with the stagemonitor.profiler.minExecutionTimeNanos option, trying to get the call tree to show something. All I get is the following:

The time was occassionally like 3000 ms but as I reduce the stagemonitor.profiler.minExecutionTimeNanos option all I see is this time goes up, and no entries are shown in the call tree.

Am I missing something?

I have set org.stagemonitor=DEBUG in my log4j.properties file.
During startup, no log entries were generated (tailing and greping).
During the request, I copied this part of the log file out: https://gist.github.com/thedanielgray/7dd614a8e2dcc922762f2aaa6b0c7526

The text was updated successfully, but these errors were encountered:

See also stagemonitor/stagemonitor-mailinglist#41

felixbarny · 2017-03-30T09:18:52Z

Hi Daniel,

you have to set stagemonitor.instrument.include. The documentation was wrong. This setting is not optional. I've just fixed the documentation in master.

danielthegray · 2017-05-24T14:10:49Z

Hi, thanks for the info!!

I have added:
stagemonitor.instrument.include=com.*
to my stagemonitor.properties file and the result is the same (no expanding of the call tree).

I then tried:
stagemonitor.instrument.include=com.*,net.*,org.*
and once again, the result was the same. (empty call stack both in the web view and in the log)

2017-05-24 16:16:37,399 [async-request-reporter] INFO  org.stagemonitor.requestmonitor.reporter.LogRequestTraceReporter - 
########## PerformanceStats ##########
GET /portal/app/deal-facilities{param=EP_26a50d93495cea90c88} (200)
id:     a0e3c2fa-41f6-4fe2-b8c1-0063035574da
name:   GET /app/deal-facilities
referer: http://localhost:8081/portal/app/deal-one-deal?param=EP_3556ec0024c82c66
accept-language: en-US,en;q=0.8
host: localhost:8081
upgrade-insecure-requests: 1
connection: keep-alive
accept-encoding: gzip, deflate, sdch, br
user-agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36
accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
----------------------------------------------------------------------
Selftime (ms)              Total (ms)                 Method signature
----------------------------------------------------------------------
000838.85  100% |||||||||| 000838.85  100% |||||||||| GET /app/deal-facilities
Printing stats took 0 ms
######################################

Is there anything else I could check out?

felixbarny · 2017-05-24T14:55:51Z

Wildcards are not allowed. Use com or better a more specific sub package. Daniel Gray <notifications@github.com> schrieb am Mi., 24. Mai 2017 16:10:

…

I have added: stagemonitor.instrument.include=com.* to my stagemonitor.properties file and the result is the same (no expanding of the call tree). — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#41 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ACEDCJ4tm28fqYZq_Q5c2uim9GjMCxuWks5r9DpqgaJpZM4MtI_k> .

danielthegray · 2017-05-29T06:54:58Z

Changed it to: stagemonitor.instrument.include=com,net,org and still, no call tree.
Also tried the following:
stagemonitor.instrument.include=com
stagemonitor.instrument.include=org
And neither one made a call tree appear (the web UI still has an empty call tree, and the log still shows

----------------------------------------------------------------------
Selftime (ms)              Total (ms)                 Method signature
----------------------------------------------------------------------
004655.52  100% |||||||||| 004655.52  100% |||||||||| GET /app/deal-facilities
Printing stats took 2 ms
######################################

in all cases.

felixbarny · 2017-05-29T07:06:07Z

That's strange...

Could you set stagemonitor.instrument.debug=true maybe something it logs something interesting about the instrumentation process then.

Also, please set a break point at org.stagemonitor.tracing.profiler.Profiler#start to see wether it gets invoked.

You generally really don't want to instrument all com, net and org packages. It's recommended to only instrument your application like org.your.app.

as I reduce the stagemonitor.profiler.minExecutionTimeNanos option all I see is this time goes up

That seems to be a sign that something is happening at least

danielthegray · 2017-05-29T15:05:52Z

With the following stagemonitor.properties file:

stagemonitor.profiler.active=true
stagemonitor.web.widget.enabled=true
stagemonitor.internal.monitoring=true
stagemonitor.instrument.debug=true
stagemonitor.elasticsearch.configurationSource.deactivateStagemonitorIfEsIsDown=false
stagemonitor.instanceName=tomcat-1
stagemonitor.applicationName=myApp
stagemonitor.profiler.logCallStacks=true
stagemonitor.instrument.include=com,org,net
stagemonitor.instrument.excludeContaining=
stagemonitor.requestmonitor.cpuTime=true

I have the following log trace:
https://gist.github.com/thedanielgray/562e45549a480656921c77284661b445

The only Profiler class I find is in package org.stagemonitor.requestmonitor.profiler, not in org.stagemonitor.tracing.profiler. There, the breakpoint set in the start() method was not called, but was activated/loaded when I navigated for the first time:

The web UI still shows the empty call tree and the log (as you can see in the gist) is also empty. The fact that the breakpoint is never hit is a telling sign I guess.

You generally really don't want to instrument all com, net and org packages. It's recommended to only instrument your application like org.your.app.

Sure, I tried that at first, but right now I'm at the point of just trying to get something to show up.

Thanks for your help!

hrzbrg · 2017-05-31T17:25:39Z

Hey, check whether the Byte Buddy Agent is loaded correctly. That was the issue for me.

danielthegray · 2017-08-24T12:28:45Z

Thank you for the idea!

My configuration is still:

stagemonitor.profiler.active=true
stagemonitor.web.widget.enabled=true
stagemonitor.internal.monitoring=true
stagemonitor.elasticsearch.configurationSource.deactivateStagemonitorIfEsIsDown=false
stagemonitor.applicationName=app
stagemonitor.profiler.logCallStacks=true
stagemonitor.instrument.include=com
stagemonitor.instrument.excludeContaining=
stagemonitor.requestmonitor.cpuTime=true

I added the following directive to the Run Configuration:
"-javaagent:C:\Users\myuser\.gradle\caches\modules-2\files-2.1\net.bytebuddy\byte-buddy-agent\1.5.7\8150404a82aa17995c2242900d90eda727328aa3\byte-buddy-agent-1.5.7.jar"
And saw:
Aug 24, 2017 2:11:44 PM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -javaagent:C:\Users\candidate\.gradle\caches\modules-2\files-2.1\net.bytebuddy\byte-buddy-agent\1.5.7\8150404a82aa17995c2242900d90eda727328aa3\byte-buddy-agent-1.5.7.jar
in the log file on booting.

And I'm still getting an empty call tree:

2017-08-24 14:27:38,305 [async-request-reporter] INFO  org.stagemonitor.requestmonitor.reporter.LogRequestTraceReporter - 
########## PerformanceStats ##########
GET /app-portal/app/portfolio{} (200)
id:     3f1a425a-4104-4a84-a738-0941f5a14237
name:   GET /app/portfolio
referer: http://localhost:8081/app-portal/app/login
accept-language: en-US,en;q=0.8
host: localhost:8081
upgrade-insecure-requests: 1
connection: keep-alive
cache-control: max-age=0
accept-encoding: gzip, deflate, br
user-agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.101 Safari/537.36
accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
----------------------------------------------------------------------
Selftime (ms)              Total (ms)                 Method signature
----------------------------------------------------------------------
004555.24  100% |||||||||| 004555.24  100% |||||||||| GET /app/portfolio
Printing stats took 4 ms
######################################

Still no call tree in the web UI either :(

felixbarny · 2017-08-24T12:32:06Z

Are you using stagemonitor 0.82.0? If so, please paste the status and configurations which are logged on startup.

craigvphillips · 2017-08-24T21:01:44Z

Having same problem with:

-Dstagemonitor.internal.monitoring=true -Dstagemonitor.reporting.jmx=true -Dstagemonitor.web.widget.enabled=true -Dstagemonitor.profiler.active=true -Dstagemonitor.instrument.include=com

felixbarny · 2017-08-24T21:14:47Z

Then please also paste the output of the status and configuration startup logs of stagemonitor 0.82.0. craigvphillips <notifications@github.com> schrieb am Do., 24. Aug. 2017 23:01:

…

Having same problem with: -Dstagemonitor.internal.monitoring=true -Dstagemonitor.reporting.jmx=true -Dstagemonitor.web.widget.enabled=true -Dstagemonitor.profiler.active=true -Dstagemonitor.instrument.include=com — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#41 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ACEDCNJRuW-vS7l16VTJ_7heCoLkxRBnks5sbeS5gaJpZM4MtI_k> .

craigvphillips · 2017-08-24T21:58:21Z

Sooo, I'm a devops guy and I stuck the jars in an existing app.

Stupid question time.. where does it log?

danielthegray · 2017-08-25T07:04:16Z

Are you using stagemonitor 0.82.0? If so, please paste the status and configurations which are logged on startup.

No, I get the JAR from Maven Central. The core and JVM artifacts have version 0.82.0, but the stagemonitor-web package is still on version 0.31.0. Has that package been deprecated?

felixbarny · 2017-08-25T07:08:14Z

Yes, its now web-servlet Daniel Gray <notifications@github.com> schrieb am Fr., 25. Aug. 2017 09:04:

…

Are you using stagemonitor 0.82.0? If so, please paste the status and configurations which are logged on startup. No, I get the JAR from Maven Central. The core and JVM artifacts have version 0.82.0, but the stagemonitor-web package is still on version 0.31.0. Has that package been deprecated? — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#41 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ACEDCDegA18N_kosiEtnFXSVXWGhCEvIks5sbnHxgaJpZM4MtI_k> .

felixbarny · 2017-08-25T09:23:55Z

where does it log?

That highly depends on your application. Stagemonitor just logs into your standard application logs. Maybe you're lucky and you have a log4j.xml under WEB-INF/classes where you can find the location of your logs. Another candidate is the /logs directory of your application server.

danielthegray · 2017-08-25T09:59:37Z

With StageMonitor 0.82.0 and the following config file:

stagemonitor.profiler.active=true
stagemonitor.web.widget.enabled=true
stagemonitor.internal.monitoring=true
stagemonitor.reporting.jmx=true
stagemonitor.elasticsearch.configurationSource.deactivateStagemonitorIfEsIsDown=false
stagemonitor.applicationName=app
stagemonitor.instanceName=Tomcat1
stagemonitor.profiler.logCallStacks=true
stagemonitor.instrument.include=com,org,net
stagemonitor.instrument.excludeContaining=
stagemonitor.requestmonitor.cpuTime=true
stagemonitor.instrument.debug=true

And specifying the byte-buddy-agent Javaagent as follows:
"-javaagent:C:\Users\myuser\.gradle\caches\modules-2\files-2.1\net.bytebuddy\byte-buddy-agent\1.6.13\ca405fc7c03fa34ae837360477f6ef4e8a92f371\byte-buddy-agent-1.6.13.jar"
The server fails to start. I get the following log trace:
https://gist.github.com/thedanielgray/51117b3e6f2132a42135a9615abb4685

felixbarny · 2017-08-25T10:03:35Z

Please don't set stagemonitor.instrument.include=com,org,net but rather to the package name of you application like stagemonitor.instrument.include=com.my.app

danielthegray · 2017-08-25T10:38:00Z

OK!! It finally works! Specifying the -javaagent and setting the stagemonitor.instrument.include directive to my app package worked. Thank you!

However, I had to disable JRebel for it to work, otherwise I got this error:

2017-08-25 12:32:30,412 [localhost-startStop-1] WARN  org.springframework.web.context.support.XmlWebApplicationContext - Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'entityManagerFactory' defined in class path resource [configuration/spring-config/hibernate-context.xml]: Invocation of init method failed; nested exception is java.lang.VerifyError: Bad <init> method call
Exception Details:
  Location:
    com/app/datamodel/to/HelpFaqTO.<init>(Lcom/zeroturnaround/jrebelbase/i;)V @2: invokespecial
  Reason:
    Type 'com/zeroturnaround/jrebelbase/c' is not assignable to 'com/app/datamodel/to/HelpFaqTO'
  Bytecode:
    0x0000000: 2a2b b700 b8b1                         

2017-08-25 12:32:30,488 [localhost-startStop-1] ERROR org.springframework.web.context.ContextLoader - Context initialization failed
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'entityManagerFactory' defined in class path resource [configuration/spring-config/hibernate-context.xml]: Invocation of init method failed; nested exception is java.lang.VerifyError: Bad <init> method call
Exception Details:
  Location:
    com/app/datamodel/to/HelpFaqTO.<init>(Lcom/zeroturnaround/jrebelbase/i;)V @2: invokespecial
  Reason:
    Type 'com/zeroturnaround/jrebelbase/c' is not assignable to 'com/app/datamodel/to/HelpFaqTO'
  Bytecode:
    0x0000000: 2a2b b700 b8b1

And several similar errors for other classes.

felixbarny · 2017-08-25T11:12:35Z

Great to hear :)

Also thx for reporting the jrebel issue. I was not aware of that yet. But tbh, I don't know what causes that.

craigvphillips · 2017-08-25T18:04:48Z

Is it a requirement to run byte-buddy agent?

danielthegray · 2017-08-25T18:07:15Z

According to what I read in the current documentation, it seems so. I tried without and it didn't work.

…

On Aug 25, 2017 20:04, "craigvphillips" ***@***.***> wrote: Is it a requirement to run byte-buddy agent? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#41 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AHFxDJApqHai1TQAeu9VSz6EXQlCL4u_ks5sbwzBgaJpZM4MtI_k> .

felixbarny · 2017-08-25T18:43:08Z

Is it a requirement to run byte-buddy agent?

When running on a JDK, you don't have to specify the javaagent. Only when you are using a JRE.

felixbarny pushed a commit to stagemonitor/stagemonitor that referenced this issue Mar 30, 2017

Fix documentation for stagemonitor.instrument.include

8179808

See also stagemonitor/stagemonitor-mailinglist#41

felixbarny mentioned this issue May 31, 2017

General Questions for Tomcat Webapps #44

Open

motobeats mentioned this issue May 4, 2018

Call Tree Always Empty on Tomcat #73

Open

danielthegray closed this as completed Sep 28, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Call tree always empty #41

Call tree always empty #41

danielthegray commented Mar 29, 2017

felixbarny commented Mar 30, 2017

danielthegray commented May 24, 2017 •

edited

Loading

felixbarny commented May 24, 2017 via email

danielthegray commented May 29, 2017 •

edited

Loading

felixbarny commented May 29, 2017

danielthegray commented May 29, 2017 •

edited

Loading

hrzbrg commented May 31, 2017

danielthegray commented Aug 24, 2017

felixbarny commented Aug 24, 2017

craigvphillips commented Aug 24, 2017

felixbarny commented Aug 24, 2017 via email

craigvphillips commented Aug 24, 2017

danielthegray commented Aug 25, 2017 •

edited

Loading

felixbarny commented Aug 25, 2017 via email

felixbarny commented Aug 25, 2017

danielthegray commented Aug 25, 2017

felixbarny commented Aug 25, 2017

danielthegray commented Aug 25, 2017

felixbarny commented Aug 25, 2017

craigvphillips commented Aug 25, 2017

danielthegray commented Aug 25, 2017 via email

felixbarny commented Aug 25, 2017

Call tree always empty #41

Call tree always empty #41

Comments

danielthegray commented Mar 29, 2017

felixbarny commented Mar 30, 2017

danielthegray commented May 24, 2017 • edited Loading

felixbarny commented May 24, 2017 via email

danielthegray commented May 29, 2017 • edited Loading

felixbarny commented May 29, 2017

danielthegray commented May 29, 2017 • edited Loading

hrzbrg commented May 31, 2017

danielthegray commented Aug 24, 2017

felixbarny commented Aug 24, 2017

craigvphillips commented Aug 24, 2017

felixbarny commented Aug 24, 2017 via email

craigvphillips commented Aug 24, 2017

danielthegray commented Aug 25, 2017 • edited Loading

felixbarny commented Aug 25, 2017 via email

felixbarny commented Aug 25, 2017

danielthegray commented Aug 25, 2017

felixbarny commented Aug 25, 2017

danielthegray commented Aug 25, 2017

felixbarny commented Aug 25, 2017

craigvphillips commented Aug 25, 2017

danielthegray commented Aug 25, 2017 via email

felixbarny commented Aug 25, 2017

danielthegray commented May 24, 2017 •

edited

Loading

danielthegray commented May 29, 2017 •

edited

Loading

danielthegray commented May 29, 2017 •

edited

Loading

danielthegray commented Aug 25, 2017 •

edited

Loading