Call tree always empty

[danielthegray]

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

[felixbarny]

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]

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]

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 https://github.com/stagemonitor/stagemonitor-mailinglist/issues/41#issuecomment-303735642, or mute the thread https://github.com/notifications/unsubscribe-auth/ACEDCJ4tm28fqYZq_Q5c2uim9GjMCxuWks5r9DpqgaJpZM4MtI_k .

[danielthegray]

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]

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]

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]

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

[danielthegray]

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]

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

[craigvphillips]

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]

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 https://github.com/stagemonitor/stagemonitor-mailinglist/issues/41#issuecomment-324756656, or mute the thread https://github.com/notifications/unsubscribe-auth/ACEDCNJRuW-vS7l16VTJ_7heCoLkxRBnks5sbeS5gaJpZM4MtI_k .

[craigvphillips]

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

Stupid question time.. where does it log?

[danielthegray]

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]

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 https://github.com/stagemonitor/stagemonitor-mailinglist/issues/41#issuecomment-324840380, or mute the thread https://github.com/notifications/unsubscribe-auth/ACEDCDegA18N_kosiEtnFXSVXWGhCEvIks5sbnHxgaJpZM4MtI_k .

[felixbarny]

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]

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]

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]

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]

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]

Is it a requirement to run byte-buddy agent?

[danielthegray]

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" notifications@github.com 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 https://github.com/stagemonitor/stagemonitor-mailinglist/issues/41#issuecomment-324995965, or mute the thread https://github.com/notifications/unsubscribe-auth/AHFxDJApqHai1TQAeu9VSz6EXQlCL4u_ks5sbwzBgaJpZM4MtI_k .

[felixbarny]

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.