Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

servery map only the Tomcat icon, no Data for Response Summary and Load #4111

Closed
leogoing opened this issue May 9, 2018 · 30 comments
Closed

servery map only the Tomcat icon, no Data for Response Summary and Load #4111

leogoing opened this issue May 9, 2018 · 30 comments
Labels
question stale

Comments

@leogoing
Copy link

leogoing commented May 9, 2018 •
edited

Description

Why is Servery map only the Tomcat icon. Response Summary and Load also has no data
1525856421949

There's actually mysql in the data:

1525856591574

Everyone ... Please help me

Environment

  • Pinpoint version: 1.7.3
  • OS, WAS, affected library, etc: CentOS
  • Additional details (e.g. how your collector/web is set up): Tomcat 7 jdk 8

Additional Info
@leogoing leogoing changed the title servery map only the Tomcat icon servery map only the Tomcat icon, no Data for Response Summary and Load May 9, 2018
@leogoing
Copy link
Author

leogoing commented May 9, 2018

Is there a problem with my configuration?

@Xylus
Copy link
Contributor

Xylus commented May 10, 2018

Hi @leogoing
that is very weird.
Is there anything strange going in the web/collector log?
Can you make sure data is inserted into ApplicationMapStatisticsCallee_Ver2, ApplicationMapStatisticsCaller_Ver2, and ApplicationMapStatisticsSelf_Ver2 tables?

@Xylus Xylus added the question label May 10, 2018
@leogoing
Copy link
Author

I don't know what the log represents, but there is no error. I'll see if these tables's have any value : )

@leogoing
Copy link
Author

I found out why I didn't have mysql information, I used Tomcat DBCP pool, but it doesn't support this pool

@leogoing
Copy link
Author

so why Response Summary and Load has no data ?

@minwoo-jung
Copy link
Member

minwoo-jung commented May 17, 2018 •
edited

Hi @leogoing
I think you should debugging and see detail log containg debug level.

  1. When you request test server. you see agent log and collector log.
  2. when you see main page in pinpoint-web. we see pinpoint web log.

There are various possibilities, but I suspect whether callee and caller data insert hbase table.
If you can not find strange log. show me full log when you request test server and call main page pinpoint web.

@leogoing
Copy link
Author

ApplicationMapStatisticsCallee_Ver2, ApplicationMapStatisticsCaller_Ver2, and ApplicationMapStatisticsSelf_Ver2 has no data.
Now, I've turned the log level to debug.

this is agent log：
2018-05-16 16:56:32 INFO Sending AgentInfo TAgentInfo(hostname:Hexindai-XX, ip:fe80:0:0:0:98d9:3aff:fee6:e556%3, ports:, agentId:settlment, applicationName:test, serviceType:1010, pid:6331, agentVersion:1.7.3, vmVersion:1.7.0_71, startTimestamp:1526027326774, serverMetaData:TServerMetaData(serverInfo:Apache Tomcat/7.0.73, vmArgs:[-Djava.util.logging.config.file=/export/home/tomcat/domains/settlement.hexindai.com/server1/conf/logging.properties, -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager, -Djava.library.path=/usr/local/lib, -Xms2048m, -Xmx4096m, -XX:MaxPermSize=512m, -Djava.awt.headless=true, -Dsun.net.client.defaultConnectTimeout=60000, -Dsun.net.client.defaultReadTimeout=60000, -Djmagick.systemclassloader=no, -Dnetworkaddress.cache.ttl=300, -Dsun.net.inetaddr.ttl=300, -Djdk.tls.ephemeralDHKeySize=2048, -Dcom.sun.management.jmxremote=true, -Djava.rmi.server.hostname=172.20.10.32, -Dcom.sun.management.jmxremote.port=9999, -Dcom.sun.management.jmxremote.ssl=false, -Dcom.sun.managementote.ssl=false, -Dcom.sun.management.jmxremote.authenticate=false, -javaagent:/export/apm/pinpoint-agent/pinpoint-bootstrap-1.7.3.jar, -Dpinpoint.agentId=settlment, -Dpinpoint.applicationName=test, -XX:+UnlockCommercialFeatures, -XX:+FlightRecorder, -Djava.endorsed.dirs=/export/servers/tomcat7.0.57/endorsed, -Dcatalina.base=/export/home/tomcat/domains/settlement.hexindai.com/server1, -Dcatalina.home=/export/servers/tomcat7.0.57, -Djava.io.tmpdir=/export/home/tomcat/domains/settlement.hexindai.com/server1/temp], serviceInfos:[TServiceInfo(serviceName:Catalina/localhost/, serviceLibs:[aspectjrt-1.7.4.jar, aspectjweaver-1.7.4.jar, classmate-1.1.0.jar, commons-beanutils-1.9.2.jar, commons-codec-1.9.jar, commons-collections-3.2.1.jar, commons-io-2.1.jar, commons-lang3-3.4.jar, commons-logging-1.2.jar, fastjson-1.2.15.jar, hibernate-validator-5.2.4.Final.jar, httpclient-4.5.2.jar, httpcore-4.4.4.jar, jackson-annotations-2.8.0.jar, jackson-core-2.8.11.jar, jackson-databind-2.8.11.jar, jboss-logging-3.2.1.Final.jar, jcl-over-slf4j-1.7.21.jar, joda-time-2.9.7.jar, jstl-1.2.jar, jul-to-slf4j-1.7.21.jar, log4j-over-slf4j-1.7.21.jar, logback-classic-1.1.7.jar, logback-core-1.1.7.jar, mybatis-3.4.1.jar, mybatis-spring-1.3.0.jar, mysql-connector-java-5.1.37.jar, settlement-common-0.0.1-SNAPSHOT.jar, settlement-rpc-0.0.1-SNAPSHOT.jar, slf4j-api-1.7.21.jar, spring-aop-4.3.1.RELEASE.jar, spring-beans-4.3.1.RELEASE.jar, spring-context-4.3.1.RELEASE.jar, spring-context-support-4.3.1.RELEASE.jar, spring-core-4.3.1.RELEASE.jar, spring-expression-4.3.1.RELEASE.jar, spring-jdbc-4.3.1.RELEASE.jar, spring-tx-4.3.1.RELEASE.jar, spring-web-4.3.1.RELEASE.jar, spring-webmvc-4.3.1.RELEASE.jar, tomcat-jdbc-7.0.54.jar, tomcat-juli-7.0.54.jar, validation-api-1.1.0.Final.jar])]), jvmInfo:TJvmInfo(version:0, vmVersion:1.7.0_71, gcType:PARALLEL))
2018-05-16 16:56:32 INFO AgentInfo sent.
2018-05-17 16:56:32 INFO Sending AgentInfo TAgentInfo(hostname:Hexindai-XX, ip:fe80:0:0:0:98d9:3aff:fee6:e556%3, ports:, agentId:settlment, applicationName:test, serviceType:1010, pid:6331, agentVersion:1.7.3, vmVersion:1.7.0_71, startTimestamp:1526027326774, serverMetaData:TServerMetaData(serverInfo:Apache Tomcat/7.0.73, vmArgs:[-Djava.util.logging.config.file=/export/home/tomcat/domains/settlement.hexindai.com/server1/conf/logging.properties, -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager, -Djava.library.path=/usr/local/lib, -Xms2048m, -Xmx4096m, -XX:MaxPermSize=512m, -Djava.awt.headless=true, -Dsun.net.client.defaultConnectTimeout=60000, -Dsun.net.client.defaultReadTimeout=60000, -Djmagick.systemclassloader=no, -Dnetworkaddress.cache.ttl=300, -Dsun.net.inetaddr.ttl=300, -Djdk.tls.ephemeralDHKeySize=2048, -Dcom.sun.management.jmxremote=true, -Djava.rmi.server.hostname=172.20.10.32, -Dcom.sun.management.jmxremote.port=9999, -Dcom.sun.management.jmxremote.ssl=false, -Dcom.sun.managementote.ssl=false, -Dcom.sun.management.jmxremote.authenticate=false, -javaagent:/export/apm/pinpoint-agent/pinpoint-bootstrap-1.7.3.jar, -Dpinpoint.agentId=settlment, -Dpinpoint.applicationName=test, -XX:+UnlockCommercialFeatures, -XX:+FlightRecorder, -Djava.endorsed.dirs=/export/servers/tomcat7.0.57/endorsed, -Dcatalina.base=/export/home/tomcat/domains/settlement.hexindai.com/server1, -Dcatalina.home=/export/servers/tomcat7.0.57, -Djava.io.tmpdir=/export/home/tomcat/domains/settlement.hexindai.com/server1/temp], serviceInfos:[TServiceInfo(serviceName:Catalina/localhost/, serviceLibs:[aspectjrt-1.7.4.jar, aspectjweaver-1.7.4.jar, classmate-1.1.0.jar, commons-beanutils-1.9.2.jar, commons-codec-1.9.jar, commons-collections-3.2.1.jar, commons-io-2.1.jar, commons-lang3-3.4.jar, commons-logging-1.2.jar, fastjson-1.2.15.jar, hibernate-validator-5.2.4.Final.jar, httpclient-4.5.2.jar, httpcore-4.4.4.jar, jackson-annotations-2.8.0.jar, jackson-core-2.8.11.jar, jackson-databind-2.8.11.jar, jboss-logging-3.2.1.Final.jar, jcl-over-slf4j-1.7.21.jar, joda-time-2.9.7.jar, jstl-1.2.jar, jul-to-slf4j-1.7.21.jar, log4j-over-slf4j-1.7.21.jar, logback-classic-1.1.7.jar, logback-core-1.1.7.jar, mybatis-3.4.1.jar, mybatis-spring-1.3.0.jar, mysql-connector-java-5.1.37.jar, settlement-common-0.0.1-SNAPSHOT.jar, settlement-rpc-0.0.1-SNAPSHOT.jar, slf4j-api-1.7.21.jar, spring-aop-4.3.1.RELEASE.jar, spring-beans-4.3.1.RELEASE.jar, spring-context-4.3.1.RELEASE.jar, spring-context-support-4.3.1.RELEASE.jar, spring-core-4.3.1.RELEASE.jar, spring-expression-4.3.1.RELEASE.jar, spring-jdbc-4.3.1.RELEASE.jar, spring-tx-4.3.1.RELEASE.jar, spring-web-4.3.1.RELEASE.jar, spring-webmvc-4.3.1.RELEASE.jar, tomcat-jdbc-7.0.54.jar, tomcat-juli-7.0.54.jar, validation-api-1.1.0.Final.jar])]), jvmInfo:TJvmInfo(version:0, vmVersion:1.7.0_71, gcType:PARALLEL))
2018-05-17 16:56:32 INFO AgentInfo sent.

This is collector log:

2018-05-18 10:02:01 DEBUG [Caller] test (USER) msg -> test (TOMCAT)[msg]
2018-05-18 10:02:01 DEBUG [Callee] test (TOMCAT) <- test (USER)[msg]
2018-05-18 10:02:01 DEBUG [Received] test (TOMCAT)[msg]
2018-05-18 10:02:01 DEBUG handle spanEvent size:9
2018-05-18 10:02:01 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:01 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:01 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:01 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:01 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:01 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:01 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:01 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:02 DEBUG flush HbaseMapStatisticsCallerDao to [ApplicationMapStatisticsCallee_Ver2] Increment:2
2018-05-18 10:02:02 DEBUG flush HbaseMapStatisticsCalleeDao to [ApplicationMapStatisticsCaller_Ver2] Increment:2
2018-05-18 10:02:02 DEBUG flush HbaseMapResponseTimeDao to [ApplicationMapStatisticsSelf_Ver2] Increment:1
2018-05-18 10:02:02 DEBUG Received TAgentStatBatch=TAgentStatBatch(agentId:settlment, startTimestamp:1526027326774, agentStats:[TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608897449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:823266240, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.001027221366204417, systemCpuLoad:0.027221366204417053), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608902449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:823266240, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0010178117048346056, systemCpuLoad:0.022391857506361322), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608907449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825141944, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020512820512820513, systemCpuLoad:0.03128205128205128), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608912449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825141944, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:5.081300813008131E-4, systemCpuLoad:0.04268292682926829), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608917449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825141944, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0010230179028132991, systemCpuLoad:0.02557544757033248), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608922449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825217464, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0021482277121374865, systemCpuLoad:0.07357679914070892), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime())])
2018-05-18 10:02:02 DEBUG Received TAgentStatBatch=TAgentStatBatch(agentId:settlment, startTimestamp:1526027326774, agentStats:[TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608897449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:823266240, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.001027221366204417, systemCpuLoad:0.027221366204417053), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608902449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:823266240, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0010178117048346056, systemCpuLoad:0.022391857506361322), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608907449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825141944, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020512820512820513, systemCpuLoad:0.03128205128205128), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608912449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825141944, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:5.081300813008131E-4, systemCpuLoad:0.04268292682926829), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608917449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825141944, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0010230179028132991, systemCpuLoad:0.02557544757033248), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:settlment, startTimestamp:1526027326774, timestamp:1526608922449, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:825217464, jvmMemoryHeapMax:3817865216, jvmMemoryNonHeapUsed:68228640, jvmMemoryNonHeapMax:587202560, jvmGcOldCount:0, jvmGcOldTime:0), cpuLoad:TCpuLoad(jvmCpuLoad:0.0021482277121374865, systemCpuLoad:0.07357679914070892), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime())])
2018-05-18 10:02:06 DEBUG Received SPAN=TSpan(agentId:msg, applicationName:test, agentStartTime:1525921566817, transactionId:00 01 E1 A0 8D C0 B4 2C D7 06, spanId:-6740084998874655828, startTime:1526608926267, elapsed:13, rpc:/hexin-msg/msg/asyncSendMsg, serviceType:1010, endPoint:172.20.10.32:8080, remoteAddr:172.20.10.56, annotations:[TAnnotation(key:46, value:)], flag:0, err:0, spanEventList:[TSpanEvent(sequence:3, startElapsed:4, serviceType:8200, endPoint:172.20.10.32:6000, annotations:[TAnnotation(key:310, value:<TAnnotationValue intBooleanIntBooleanValue:TIntBooleanIntBooleanValue(intValue1:0, boolValue1:false, intValue2:0, boolValue2:false)>)], depth:4, destinationId:REDIS, apiId:361), TSpanEvent(sequence:4, startElapsed:4, serviceType:8200, endPoint:172.20.10.32:6000, annotations:[TAnnotation(key:310, value:<TAnnotationValue intBooleanIntBooleanValue:TIntBooleanIntBooleanValue(intValue1:0, boolValue1:false, intValue2:0, boolValue2:false)>)], destinationId:REDIS, apiId:-300), TSpanEvent(sequence:5, startElapsed:5, serviceType:8200, endPoint:172.20.10.32:6000, annotations:[TAnnotation(key:310, value:<TAnnotationValue intBooleanIntBooleanValue:TIntBooleanIntBooleanValue(intValue1:0, boolValue1:false, intValue2:0, boolValue2:false)>)], destinationId:REDIS, apiId:361), TSpanEvent(sequence:6, startElapsed:5, serviceType:8200, endPoint:172.20.10.32:6000, annotations:[TAnnotation(key:310, value:<TAnnotationValue intBooleanIntBooleanValue:TIntBooleanIntBooleanValue(intValue1:0, boolValue1:false, intValue2:0, boolValue2:false)>)], destinationId:REDIS, apiId:-383), TSpanEvent(sequence:8, startElapsed:8, serviceType:5011, annotations:[TAnnotation(key:9001, value:)], depth:5, apiId:-402), TSpanEvent(sequence:7, startElapsed:8, endElapsed:3, serviceType:5071, apiId:160), TSpanEvent(sequence:2, startElapsed:0, endElapsed:13, serviceType:5071, depth:3, apiId:-110), TSpanEvent(sequence:1, startElapsed:0, endElapsed:13, serviceType:5051, depth:2, apiId:-94), TSpanEvent(sequence:0, startElapsed:0, endElapsed:13, serviceType:1011, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:sysname=HXDZSWYXGS&messages=[{"dielectricCode":"2,","content":"今天是您生日，愿所有的快乐、幸福、好运都围绕在您身边。特别...(235)>)], depth:1, apiId:2)], apiId:3, applicationServiceType:1010, loggingTransactionInfo:0)
2018-05-18 10:02:06 DEBUG [Caller] test (USER) msg -> test (TOMCAT)[msg]
2018-05-18 10:02:06 DEBUG [Callee] test (TOMCAT) <- test (USER)[msg]
2018-05-18 10:02:06 DEBUG [Received] test (TOMCAT)[msg]
2018-05-18 10:02:06 DEBUG handle spanEvent size:9
2018-05-18 10:02:06 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:06 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:06 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:06 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:06 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:06 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:06 DEBUG [Caller] test (TOMCAT) msg -> REDIS (REDIS)[172.20.10.32:6000]
2018-05-18 10:02:06 DEBUG [Callee] REDIS (REDIS) <- test (TOMCAT)[172.20.10.32:8080]
2018-05-18 10:02:06 DEBUG flush HbaseMapStatisticsCallerDao to [ApplicationMapStatisticsCallee_Ver2] Increment:2
2018-05-18 10:02:06 DEBUG flush HbaseMapStatisticsCalleeDao to [ApplicationMapStatisticsCaller_Ver2] Increment:2
2018-05-18 10:02:06 DEBUG flush HbaseMapResponseTimeDao to [ApplicationMapStatisticsSelf_Ver2] Increment:1
2018-05-18 10:02:07 DEBUG Got ping response for sessionid: 0x100000742ef004f after 1ms

@leogoing
Copy link
Author

This is web log:

2018-05-18 10:07:49 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint]
2018-05-18 10:07:49 DEBUG Looking up handler method for path /configuration.pinpoint
2018-05-18 10:07:49 DEBUG Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.navercorp.pinpoint.web.controller.ConfigController.getProperties(java.lang.String)]
2018-05-18 10:07:49 DEBUG Returning cached instance of singleton bean 'configController'
2018-05-18 10:07:49 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint] is: -1
2018-05-18 10:07:49 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/configuration.pinpoint]
2018-05-18 10:07:49 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Written [{enableServerMapRealTime=false, editUserInfo=true, sendUsage=true, openSource=true, showActiveThreadDump=true, showApplicationStat=false, showActiveThread=true, version=1.8.0-SNAPSHOT}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Looking up handler method for path /configuration.pinpoint
2018-05-18 10:07:50 DEBUG Looking up handler method for path /configuration.pinpoint
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'sqlSessionFactory'
2018-05-18 10:07:50 DEBUG Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.navercorp.pinpoint.web.controller.ConfigController.getProperties(java.lang.String)]
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'configController'
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint] is: -1
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/configuration.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.navercorp.pinpoint.web.controller.ConfigController.getProperties(java.lang.String)]
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'configController'
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint] is: -1
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/configuration.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Written [{enableServerMapRealTime=false, editUserInfo=true, sendUsage=true, openSource=true, showActiveThreadDump=true, showApplicationStat=false, showActiveThread=true, version=1.8.0-SNAPSHOT}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:50 DEBUG Written [{enableServerMapRealTime=false, editUserInfo=true, sendUsage=true, openSource=true, showActiveThreadDump=true, showApplicationStat=false, showActiveThread=true, version=1.8.0-SNAPSHOT}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Looking up handler method for path /configuration.pinpoint
2018-05-18 10:07:50 DEBUG Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.navercorp.pinpoint.web.controller.ConfigController.getProperties(java.lang.String)]
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'configController'
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint] is: -1
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/configuration.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Written [{enableServerMapRealTime=false, editUserInfo=true, sendUsage=true, openSource=true, showActiveThreadDump=true, showApplicationStat=false, showActiveThread=true, version=1.8.0-SNAPSHOT}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Looking up handler method for path /configuration.pinpoint
2018-05-18 10:07:50 DEBUG Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.navercorp.pinpoint.web.controller.ConfigController.getProperties(java.lang.String)]
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'configController'
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint] is: -1
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/configuration.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Written [{enableServerMapRealTime=false, editUserInfo=true, sendUsage=true, openSource=true, showActiveThreadDump=true, showApplicationStat=false, showActiveThread=true, version=1.8.0-SNAPSHOT}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/applications.pinpoint]
2018-05-18 10:07:50 DEBUG Looking up handler method for path /applications.pinpoint
2018-05-18 10:07:50 DEBUG Returning handler method [public com.navercorp.pinpoint.web.view.ApplicationGroup com.navercorp.pinpoint.web.controller.MainController.getApplicationGroup()]
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'mainController'
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/applications.pinpoint] is: -1
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/applications.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/applications.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint]
2018-05-18 10:07:50 DEBUG Looking up handler method for path /configuration.pinpoint
2018-05-18 10:07:50 DEBUG Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.navercorp.pinpoint.web.controller.ConfigController.getProperties(java.lang.String)]
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'configController'
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint] is: -1
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/configuration.pinpoint]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/configuration.pinpoint]
2018-05-18 10:07:50 [DEBUG](c.n.p.w.c.MainController :50 ) /applications [elastic(STAND_ALONE:1000), test(TOMCAT:1010), test2(TOMCAT:1010)]
2018-05-18 10:07:50 DEBUG Written [{enableServerMapRealTime=false, editUserInfo=true, sendUsage=true, openSource=true, showActiveThreadDump=true, showApplicationStat=false, showActiveThread=true, version=1.8.0-SNAPSHOT}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:50 DEBUG Creating instance of bean 'com.navercorp.pinpoint.web.view.ApplicationGroupSerializer'
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
2018-05-18 10:07:50 DEBUG Finished creating instance of bean 'com.navercorp.pinpoint.web.view.ApplicationGroupSerializer'
2018-05-18 10:07:50 DEBUG Creating instance of bean 'com.navercorp.pinpoint.web.view.ApplicationGroupSerializer'
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-05-18 10:07:50 DEBUG Finished creating instance of bean 'com.navercorp.pinpoint.web.view.ApplicationGroupSerializer'
2018-05-18 10:07:50 DEBUG Creating instance of bean 'com.navercorp.pinpoint.web.view.ApplicationSerializer'
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-05-18 10:07:50 DEBUG Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
2018-05-18 10:07:50 DEBUG Finished creating instance of bean 'com.navercorp.pinpoint.web.view.ApplicationSerializer'
2018-05-18 10:07:50 DEBUG Written [com.navercorp.pinpoint.web.view.ApplicationGroup@7b80cd] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:50 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/applications.pinpoint]
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/getServerMapDataV2.pinpoint]
2018-05-18 10:07:51 DEBUG Looking up handler method for path /applications.pinpoint
2018-05-18 10:07:51 DEBUG Looking up handler method for path /getServerMapDataV2.pinpoint
2018-05-18 10:07:51 DEBUG Returning handler method [public com.navercorp.pinpoint.web.view.ApplicationGroup com.navercorp.pinpoint.web.controller.MainController.getApplicationGroup()]
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'mainController'
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/applications.pinpoint] is: -1
2018-05-18 10:07:51 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/applications.pinpoint]
2018-05-18 10:07:51 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/applications.pinpoint]
2018-05-18 10:07:51 DEBUG Returning handler method [public com.navercorp.pinpoint.web.applicationmap.MapWrap com.navercorp.pinpoint.web.controller.MapController.getServerMapDataV2(java.lang.String,java.lang.String,long,long,int,int,boolean,boolean)]
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'mapController'
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/getServerMapDataV2.pinpoint] is: -1
2018-05-18 10:07:51 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/getServerMapDataV2.pinpoint]
2018-05-18 10:07:51 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/getServerMapDataV2.pinpoint]
2018-05-18 10:07:51 [DEBUG](c.n.p.w.c.MainController :50 ) /applications [elastic(STAND_ALONE:1000), test(TOMCAT:1010), test2(TOMCAT:1010)]
2018-05-18 10:07:51 DEBUG Written [com.navercorp.pinpoint.web.view.ApplicationGroup@17c8716] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:51 [INFO ](c.n.p.w.c.MapController :216) getServerMap() application:test(TOMCAT:1010) range:Range{from=1526606824000, to=1526608024000, range=1200000} searchOption:SearchOption{callerSearchDepth=4, calleeSearchDepth=4, linkSelectorType=BIDIRECTIONAL, wasOnly=false}
2018-05-18 10:07:51 [DEBUG](c.n.p.w.s.MapServiceImpl :91 ) SelectApplicationMap
2018-05-18 10:07:51 DEBUG Creating link data map for [test(TOMCAT:1010)]
2018-05-18 10:07:51 INFO depth search start. callerDepth:0, calleeDepth:0, size:1, nodes:[test(TOMCAT:1010)]
2018-05-18 10:07:51 DEBUG Finding Caller/Callee link data for test(TOMCAT:1010)
2018-05-18 10:07:51 DEBUG Finding Caller link data for test(TOMCAT:1010)
2018-05-18 10:07:51 DEBUG scan Time:Range{from=1526606819999, to=1526608020000, range s=1200}
2018-05-18 10:07:51 [DEBUG](c.n.p.c.h.HbaseTemplate2 :672) ParallelDistributedScanner createTime: 2ms
2018-05-18 10:07:51 [DEBUG](c.n.p.c.h.HbaseTemplate2 :680) ParallelDistributedScanner scanTime: 69ms
2018-05-18 10:07:51 DEBUG Caller data. null, Range{from=1526606824000, to=1526608024000, range=1200000}
2018-05-18 10:07:51 DEBUG Found Caller. count=0, caller=test(TOMCAT:1010), depth=0
2018-05-18 10:07:51 DEBUG Finding Callee link data for test(TOMCAT:1010)
2018-05-18 10:07:51 DEBUG scan time:Range{from=1526606819999, to=1526608020000, range s=1200}
2018-05-18 10:07:51 [DEBUG](c.n.p.c.h.HbaseTemplate2 :672) ParallelDistributedScanner createTime: 1ms
2018-05-18 10:07:51 [DEBUG](c.n.p.c.h.HbaseTemplate2 :680) ParallelDistributedScanner scanTime: 70ms
2018-05-18 10:07:51 DEBUG Callee data. null, Range{from=1526606824000, to=1526608024000, range=1200000}
2018-05-18 10:07:51 DEBUG Found Callee. count=0, callee=test(TOMCAT:1010), depth=0
2018-05-18 10:07:51 DEBUG depth search. callerDepth : 0, calleeDepth : 0
2018-05-18 10:07:51 INFO depth search end. callerDepth:0, calleeDepth:0
2018-05-18 10:07:51 [INFO ](c.n.p.w.a.ApplicationMapBuilder :129) Building application map
2018-05-18 10:07:51 [DEBUG](c.n.p.w.a.n.NodeListFactory :36 ) node size:0
2018-05-18 10:07:51 [DEBUG](c.n.p.w.a.n.NodeListFactory :38 ) node size:0
2018-05-18 10:07:51 [DEBUG](c.n.p.w.a.n.NodeListFactory :40 ) allNode:[]
2018-05-18 10:07:51 [DEBUG](c.n.p.w.a.l.LinkListFactory :41 ) link size:0
2018-05-18 10:07:51 [DEBUG](c.n.p.w.a.l.LinkListFactory :43 ) link size:0
2018-05-18 10:07:51 [INFO ](c.n.p.w.a.ApplicationMapBuilder :96 ) Building empty application map
2018-05-18 10:07:51 DEBUG unfiltered agentInfos [AgentInfo{applicationName='test', agentId='msg', startTimestamp=1525921566817, hostName='Hexindai-XX', ip='fe80:0:0:0:98d9:3aff:fee6:e556%docker0', ports='', serviceTypeCode=1010, pid=19733, vmVersion='1.8.0_131', agentVersion='1.7.3', jvmInfo=JvmInfoBo{version=0, jvmVersion='1.8.0_131', gcTypeName='PARALLEL'}, initialStartTimestamp=0, status=null}, AgentInfo{applicationName='test', agentId='settlment', startTimestamp=1526027326774, hostName='Hexindai-XX', ip='fe80:0:0:0:98d9:3aff:fee6:e556%3', ports='', serviceTypeCode=1010, pid=6331, vmVersion='1.7.0_71', agentVersion='1.7.3', jvmInfo=JvmInfoBo{version=0, jvmVersion='1.7.0_71', gcTypeName='PARALLEL'}, initialStartTimestamp=0, status=null}]
2018-05-18 10:07:51 DEBUG add agentInfos test(TOMCAT:1010) : [AgentInfo{applicationName='test', agentId='msg', startTimestamp=1525921566817, hostName='Hexindai-XX', ip='fe80:0:0:0:98d9:3aff:fee6:e556%docker0', ports='', serviceTypeCode=1010, pid=19733, vmVersion='1.8.0_131', agentVersion='1.7.3', jvmInfo=JvmInfoBo{version=0, jvmVersion='1.8.0_131', gcTypeName='PARALLEL'}, initialStartTimestamp=0, status=AgentStatus{agentId='msg', eventTimestamp=1526607735069, state=Running}}, AgentInfo{applicationName='test', agentId='settlment', startTimestamp=1526027326774, hostName='Hexindai-XX', ip='fe80:0:0:0:98d9:3aff:fee6:e556%3', ports='', serviceTypeCode=1010, pid=6331, vmVersion='1.7.0_71', agentVersion='1.7.3', jvmInfo=JvmInfoBo{version=0, jvmVersion='1.7.0_71', gcTypeName='PARALLEL'}, initialStartTimestamp=0, status=AgentStatus{agentId='settlment', eventTimestamp=1526607735004, state=Running}}]
2018-05-18 10:07:51 [DEBUG](c.n.p.w.a.n.ServerBuilder :109) buildPhysicalServer:[AgentInfo{applicationName='test', agentId='msg', startTimestamp=1525921566817, hostName='Hexindai-XX', ip='fe80:0:0:0:98d9:3aff:fee6:e556%docker0', ports='', serviceTypeCode=1010, pid=19733, vmVersion='1.8.0_131', agentVersion='1.7.3', jvmInfo=JvmInfoBo{version=0, jvmVersion='1.8.0_131', gcTypeName='PARALLEL'}, initialStartTimestamp=0, status=AgentStatus{agentId='msg', eventTimestamp=1526607735069, state=Running}}, AgentInfo{applicationName='test', agentId='settlment', startTimestamp=1526027326774, hostName='Hexindai-XX', ip='fe80:0:0:0:98d9:3aff:fee6:e556%3', ports='', serviceTypeCode=1010, pid=6331, vmVersion='1.7.0_71', agentVersion='1.7.3', jvmInfo=JvmInfoBo{version=0, jvmVersion='1.7.0_71', gcTypeName='PARALLEL'}, initialStartTimestamp=0, status=AgentStatus{agentId='settlment', eventTimestamp=1526607735004, state=Running}}]
2018-05-18 10:07:51 DEBUG selectResponseTime applicationName:test(TOMCAT:1010), Range{from=1526606824000, to=1526608024000, range=1200000}
2018-05-18 10:07:51 DEBUG scan time:Range{from=1526606819999, to=1526608020000, range s=1200}
2018-05-18 10:07:51 [DEBUG](c.n.p.c.h.HbaseTemplate2 :672) ParallelDistributedScanner createTime: 2ms
2018-05-18 10:07:51 [DEBUG](c.n.p.c.h.HbaseTemplate2 :680) ParallelDistributedScanner scanTime: 18ms
2018-05-18 10:07:51 DEBUG Self data []
2018-05-18 10:07:51 [INFO ](c.n.p.w.s.MapServiceImpl :118) ApplicationMap BuildTime: StopWatch 'ApplicationMap': running time (millis) = 402

ms % Task name

00223 055% ApplicationMap Hbase Io Fetch(Caller,Callee) Time
00179 045% ApplicationMap MapBuilding(Response) Time

2018-05-18 10:07:51 DEBUG Creating instance of bean 'com.navercorp.pinpoint.web.view.NodeSerializer'
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
2018-05-18 10:07:51 DEBUG Finished creating instance of bean 'com.navercorp.pinpoint.web.view.NodeSerializer'
2018-05-18 10:07:51 DEBUG Creating instance of bean 'com.navercorp.pinpoint.web.view.HistogramSerializer'
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
2018-05-18 10:07:51 DEBUG Finished creating instance of bean 'com.navercorp.pinpoint.web.view.HistogramSerializer'
2018-05-18 10:07:51 DEBUG Creating instance of bean 'com.navercorp.pinpoint.web.view.TimeCountSerializer'
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
2018-05-18 10:07:51 DEBUG Finished creating instance of bean 'com.navercorp.pinpoint.web.view.TimeCountSerializer'
2018-05-18 10:07:51 DEBUG Written [com.navercorp.pinpoint.web.applicationmap.MapWrap@127e2a4] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint]
2018-05-18 10:07:51 DEBUG Looking up handler method for path /configuration.pinpoint
2018-05-18 10:07:51 DEBUG Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.navercorp.pinpoint.web.controller.ConfigController.getProperties(java.lang.String)]
2018-05-18 10:07:51 DEBUG Returning cached instance of singleton bean 'configController'
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/configuration.pinpoint] is: -1
2018-05-18 10:07:51 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/configuration.pinpoint]
2018-05-18 10:07:51 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/configuration.pinpoint]
2018-05-18 10:07:51 DEBUG Written [{enableServerMapRealTime=false, editUserInfo=true, sendUsage=true, openSource=true, showActiveThreadDump=true, showApplicationStat=false, showActiveThread=true, version=1.8.0-SNAPSHOT}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@d51f4b]
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :1044) Null ModelAndView returned to DispatcherServlet with name 'pinpoint-web': assuming HandlerAdapter completed request handling
2018-05-18 10:07:51 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request
2018-05-18 10:07:52 [DEBUG](o.s.w.s.DispatcherServlet :865) DispatcherServlet with name 'pinpoint-web' processing GET request for [/pinpoint-web-1.8.0-SNAPSHOT/getScatterData.pinpoint]
2018-05-18 10:07:52 DEBUG Looking up handler method for path /getScatterData.pinpoint
2018-05-18 10:07:52 DEBUG Returning handler method [public org.springframework.web.servlet.ModelAndView com.navercorp.pinpoint.web.controller.ScatterChartController.getScatterData(java.lang.String,long,long,int,int,int,boolean,java.lang.String,java.lang.String,int)]
2018-05-18 10:07:52 DEBUG Returning cached instance of singleton bean 'scatterChartController'
2018-05-18 10:07:52 [DEBUG](o.s.w.s.DispatcherServlet :951) Last-Modified value for [/pinpoint-web-1.8.0-SNAPSHOT/getScatterData.pinpoint] is: -1
2018-05-18 10:07:52 [DEBUG](o.s.w.s.m.WebContentInterceptor :180) Looking up cache seconds for [/getScatterData.pinpoint]
2018-05-18 10:07:52 [DEBUG](o.s.w.s.m.WebContentInterceptor :199) Applying default cache seconds to [/getScatterData.pinpoint]
2018-05-18 10:07:52 [DEBUG](c.n.p.w.c.ScatterChartController :164) fetch scatter data. RANGE=Range{from=1526606824000, to=1526608024000, range=1200000}, X-Group-Unit:3947, Y-Group-Unit:57, LIMIT=5000, BACKWARD_DIRECTION:true, FILTER:
2018-05-18 10:07:52 DEBUG scanTraceScatterDataMadeOfDotGroup
2018-05-18 10:07:52 [DEBUG](c.n.p.c.h.HbaseTemplate2 :672) ParallelDistributedScanner createTime: 1ms
2018-05-18 10:07:52 [DEBUG](c.n.p.c.h.HbaseTemplate2 :680) ParallelDistributedScanner scanTime: 91ms
2018-05-18 10:07:52 [INFO ](c.n.p.w.c.ScatterChartController :181) Fetch scatterData time : 103ms
2018-05-18 10:07:52 DEBUG Returning cached instance of singleton bean 'jsonView'
2018-05-18 10:07:52 [DEBUG](o.s.w.s.DispatcherServlet :1276) Rendering view [org.springframework.web.servlet.view.json.MappingJackson2JsonView: name 'jsonView'] in DispatcherServlet with name 'pinpoint-web'
2018-05-18 10:07:52 [DEBUG](o.s.w.s.DispatcherServlet :1000) Successfully completed request

@Xylus
Copy link
Contributor

Xylus commented May 21, 2018

Hi @leogoing
From your web log, there doesn't seem to be any caller/callee statistics data (in ApplicationMapStatisticsCallee_Ver2, ApplicationMapStatisticsCaller_Ver2) for the query.

...
2018-05-18 10:07:51 DEBUG Caller data. null, Range{from=1526606824000, to=1526608024000, range=1200000}
...
2018-05-18 10:07:51 DEBUG Callee data. null, Range{from=1526606824000, to=1526608024000, range=1200000}
...

Additionally, your collector log is from a different time frame compared to the web log.

While this certainly isn't the cause of your issue, it does make it difficult to figure out what exactly is going on.
Would it be possible to provide collector/web logs from the same time frame for a couple of transactions as well as a screen shot of the server map generated from them?

(Also, are your ApplicationMapStatisticsCallee_Ver2 and ApplicationMapStatisticsCaller_Ver2 still empty?)

@leogoing
Copy link
Author

This is the log of agent near that time

2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2bfa77f6 handleClosedPacket() started. channel:[id: 0x8a44aa1e, /172.20.10.32:32782 => /172.20.10.30:9994]
2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2bfa77f6 stateTo() completed. Socket state change success(updateWanted:BEING_CLOSE_BY_SERVER ,before:RUN_DUPLEX ,current:BEING_CLOSE_BY_SERVER).
2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2bfa77f6 channelClosed() started.
2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2bfa77f6 stateTo() completed. Socket state change success(updateWanted:CLOSED_BY_SERVER ,before:BEING_CLOSE_BY_SERVER ,current:CLOSED_BY_SERVER).
2018-05-18 10:00:09 INFO PinpointClientHandshaker@b6e5888 handshakeAbort() started.
2018-05-18 10:00:09 INFO PinpointClientHandshaker@b6e5888 unexpected state
2018-05-18 10:00:12 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@67f17372 initReconnect() started.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@67f17372 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@67f17372 initReconnect() completed.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@67f17372 channelClosed() started.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@67f17372 exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@67f17372 stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:12 INFO PinpointClientHandshaker@bf629cf handshakeAbort() started.
2018-05-18 10:00:12 INFO PinpointClientHandshaker@bf629cf unexpected state
2018-05-18 10:00:15 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@669f4ce9 initReconnect() started.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@669f4ce9 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@669f4ce9 initReconnect() completed.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@669f4ce9 channelClosed() started.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@669f4ce9 exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@669f4ce9 stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:15 INFO PinpointClientHandshaker@1e22cd1c handshakeAbort() started.
2018-05-18 10:00:15 INFO PinpointClientHandshaker@1e22cd1c unexpected state
2018-05-18 10:00:18 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@309b2bb6 initReconnect() started.
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@309b2bb6 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@309b2bb6 initReconnect() completed.
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@309b2bb6 channelClosed() started.
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@309b2bb6 stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:18 WARN DefaultPinpointClientHandler@309b2bb6 exceptionCaught() occurred. state:CONNECT_FAILED. Caused:Connection refused: /172.20.10.30:9994
2018-05-18 10:00:18 INFO PinpointClientHandshaker@5c1db9a4 handshakeAbort() started.
2018-05-18 10:00:18 INFO PinpointClientHandshaker@5c1db9a4 unexpected state
2018-05-18 10:00:21 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:21 INFO DefaultPinpointClientHandler@243db162 initReconnect() started.
2018-05-18 10:00:21 INFO DefaultPinpointClientHandler@243db162 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:21 INFO DefaultPinpointClientHandler@243db162 initReconnect() completed.
2018-05-18 10:00:21 INFO DefaultPinpointClientHandler@243db162 channelClosed() started.
2018-05-18 10:00:21 INFO DefaultPinpointClientHandler@243db162 exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:21 INFO DefaultPinpointClientHandler@243db162 stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:21 INFO PinpointClientHandshaker@38d94a94 handshakeAbort() started.
2018-05-18 10:00:21 INFO PinpointClientHandshaker@38d94a94 unexpected state
2018-05-18 10:00:25 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@7cf3a34e initReconnect() started.
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@7cf3a34e stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@7cf3a34e initReconnect() completed.
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@7cf3a34e channelClosed() started.
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@7cf3a34e stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:25 INFO PinpointClientHandshaker@15dcfcd8 handshakeAbort() started.
2018-05-18 10:00:25 INFO PinpointClientHandshaker@15dcfcd8 unexpected state
2018-05-18 10:00:25 WARN DefaultPinpointClientHandler@7cf3a34e exceptionCaught() occurred. state:CONNECT_FAILED. Caused:Connection refused: /172.20.10.30:9994
2018-05-18 10:00:28 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@47f3cdbc initReconnect() started.
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@47f3cdbc stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@47f3cdbc initReconnect() completed.
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@47f3cdbc channelClosed() started.
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@47f3cdbc exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@47f3cdbc stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:28 INFO PinpointClientHandshaker@e8cdbae handshakeAbort() started.
2018-05-18 10:00:28 INFO PinpointClientHandshaker@e8cdbae unexpected state
2018-05-18 10:00:31 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@54b3ef9c initReconnect() started.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@54b3ef9c stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@54b3ef9c initReconnect() completed.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@54b3ef9c channelClosed() started.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@54b3ef9c exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@54b3ef9c stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:31 INFO PinpointClientHandshaker@353bd3a6 handshakeAbort() started.
2018-05-18 10:00:31 INFO PinpointClientHandshaker@353bd3a6 unexpected state
2018-05-18 10:00:34 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@654dab0f initReconnect() started.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@654dab0f stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@654dab0f initReconnect() completed.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@654dab0f channelClosed() started.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@654dab0f exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@654dab0f stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:34 INFO PinpointClientHandshaker@3c8a1f0f handshakeAbort() started.
2018-05-18 10:00:34 INFO PinpointClientHandshaker@3c8a1f0f unexpected state
2018-05-18 10:00:37 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 initReconnect() started.
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 initReconnect() completed.
2018-05-18 10:00:37 INFO reconnect success DnsSocketAddressProvider{host='172.20.10.30', port=9994}, [id: 0xcf1b828e, /172.20.10.32:5700 => /172.20.10.30:9994]
2018-05-18 10:00:37 WARN reconnectClientHandler:DefaultPinpointClientHandler@450433b0{channel=[id: 0xcf1b828e, /172.20.10.32:5700 => /172.20.10.30:9994]state=SocketState(NONE->BEING_CONNECT)}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 channelConnected() started. channel:[id: 0xcf1b828e, /172.20.10.32:5700 => /172.20.10.30:9994]
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 stateTo() completed. Socket state change success(updateWanted:CONNECTED ,before:BEING_CONNECT ,current:CONNECTED).
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 stateTo() completed. Socket state change success(updateWanted:RUN_WITHOUT_HANDSHAKE ,before:CONNECTED ,current:RUN_WITHOUT_HANDSHAKE).
2018-05-18 10:00:37 INFO PinpointClientHandshaker@e00e2e3 handshakeStart() started. channel:[id: 0xcf1b828e, /172.20.10.32:5700 => /172.20.10.30:9994]
2018-05-18 10:00:37 INFO PinpointClientHandshaker@e00e2e3 do handshake(1/2147483647). channel:[id: 0xcf1b828e, /172.20.10.32:5700 => /172.20.10.30:9994].
2018-05-18 10:00:37 INFO PinpointClientHandshaker@e00e2e3 handshakeStart() completed. channel:[id: 0xcf1b828e, /172.20.10.32:5700 => /172.20.10.30:9994], data:{serviceType=1010, socketId=19, hostName=Hexindai-XX, agentId=msg, supportCommandList=[730, 740, 750, 710], ip=fe80:0:0:0:98d9:3aff:fee6:e556%docker0, pid=19733, supportServer=true, version=1.7.3, applicationName=test, startTimestamp=1525921566817}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 channelConnected() completed.
2018-05-18 10:00:37 INFO PinpointClientHandshaker@e00e2e3 handshakeComplete() started. responsePacket:ControlHandshakeResponsePacket{requestId=0, payloadLength=27}
2018-05-18 10:00:37 INFO PinpointClientHandshaker@e00e2e3 handshakeComplete() completed. handshake-response:{code=0, subCode=2}.
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 handleHandshakePacket() started. message:ControlHandshakeResponsePacket{requestId=0, payloadLength=27}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@450433b0 stateTo() completed. Socket state change success(updateWanted:RUN_DUPLEX ,before:RUN_WITHOUT_HANDSHAKE ,current:RUN_DUPLEX).
2018-05-18 10:00:37 INFO [id: 0xcf1b828e, /172.20.10.32:5700 => /172.20.10.30:9994] handleHandshakePacket() completed. code:DUPLEX_COMMUNICATION
2018-05-18 10:01:37 INFO PinpointClientHandshaker@e00e2e3 HandshakeJob completed.
2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2038a6da handleClosedPacket() started. channel:[id: 0x95bf2dea, /172.20.10.32:32780 => /172.20.10.30:9994]
2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2038a6da stateTo() completed. Socket state change success(updateWanted:BEING_CLOSE_BY_SERVER ,before:RUN_DUPLEX ,current:BEING_CLOSE_BY_SERVER).
2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2038a6da channelClosed() started.
2018-05-18 10:00:09 INFO DefaultPinpointClientHandler@2038a6da stateTo() completed. Socket state change success(updateWanted:CLOSED_BY_SERVER ,before:BEING_CLOSE_BY_SERVER ,current:CLOSED_BY_SERVER).
2018-05-18 10:00:09 INFO PinpointClientHandshaker@1c110083 handshakeAbort() started.
2018-05-18 10:00:09 INFO PinpointClientHandshaker@1c110083 unexpected state
2018-05-18 10:00:12 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@7b4747a5 initReconnect() started.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@7b4747a5 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@7b4747a5 initReconnect() completed.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@7b4747a5 channelClosed() started.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@7b4747a5 exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:12 INFO DefaultPinpointClientHandler@7b4747a5 stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:12 INFO PinpointClientHandshaker@5fa5c191 handshakeAbort() started.
2018-05-18 10:00:12 INFO PinpointClientHandshaker@5fa5c191 unexpected state
2018-05-18 10:00:15 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@d183d9a initReconnect() started.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@d183d9a stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@d183d9a initReconnect() completed.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@d183d9a channelClosed() started.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@d183d9a exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:15 INFO DefaultPinpointClientHandler@d183d9a stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:15 INFO PinpointClientHandshaker@6cb4cb2 handshakeAbort() started.
2018-05-18 10:00:15 INFO PinpointClientHandshaker@6cb4cb2 unexpected state
2018-05-18 10:00:18 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@61ea844c initReconnect() started.
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@61ea844c stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@61ea844c initReconnect() completed.
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@61ea844c channelClosed() started.
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@61ea844c exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:18 INFO DefaultPinpointClientHandler@61ea844c stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:18 INFO PinpointClientHandshaker@3da22bd0 handshakeAbort() started.
2018-05-18 10:00:18 INFO PinpointClientHandshaker@3da22bd0 unexpected state
2018-05-18 10:00:22 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:22 INFO DefaultPinpointClientHandler@6252a1a5 initReconnect() started.
2018-05-18 10:00:22 INFO DefaultPinpointClientHandler@6252a1a5 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:22 INFO DefaultPinpointClientHandler@6252a1a5 initReconnect() completed.
2018-05-18 10:00:22 INFO DefaultPinpointClientHandler@6252a1a5 channelClosed() started.
2018-05-18 10:00:22 INFO DefaultPinpointClientHandler@6252a1a5 exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:22 INFO DefaultPinpointClientHandler@6252a1a5 stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:22 INFO PinpointClientHandshaker@e8f4e22 handshakeAbort() started.
2018-05-18 10:00:22 INFO PinpointClientHandshaker@e8f4e22 unexpected state
2018-05-18 10:00:25 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@5cf7bcff initReconnect() started.
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@5cf7bcff stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@5cf7bcff initReconnect() completed.
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@5cf7bcff exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@5cf7bcff channelClosed() started.
2018-05-18 10:00:25 INFO DefaultPinpointClientHandler@5cf7bcff stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:25 INFO PinpointClientHandshaker@6be0745d handshakeAbort() started.
2018-05-18 10:00:25 INFO PinpointClientHandshaker@6be0745d unexpected state
2018-05-18 10:00:28 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@3a6791af initReconnect() started.
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@3a6791af stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@3a6791af initReconnect() completed.
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@3a6791af channelClosed() started.
2018-05-18 10:00:28 INFO DefaultPinpointClientHandler@3a6791af stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:28 INFO PinpointClientHandshaker@6432aabd handshakeAbort() started.
2018-05-18 10:00:28 INFO PinpointClientHandshaker@6432aabd unexpected state
2018-05-18 10:00:28 WARN DefaultPinpointClientHandler@3a6791af exceptionCaught() occurred. state:CONNECT_FAILED. Caused:Connection refused: /172.20.10.30:9994
2018-05-18 10:00:31 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@4e62f2cb initReconnect() started.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@4e62f2cb stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@4e62f2cb initReconnect() completed.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@4e62f2cb exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@4e62f2cb channelClosed() started.
2018-05-18 10:00:31 INFO DefaultPinpointClientHandler@4e62f2cb stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:31 INFO PinpointClientHandshaker@35819516 handshakeAbort() started.
2018-05-18 10:00:31 INFO PinpointClientHandshaker@35819516 unexpected state
2018-05-18 10:00:34 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@563492b1 initReconnect() started.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@563492b1 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@563492b1 initReconnect() completed.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@563492b1 exceptionCaught() occurred. state:BEING_CONNECT, caused:Connection refused: /172.20.10.30:9994.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@563492b1 channelClosed() started.
2018-05-18 10:00:34 INFO DefaultPinpointClientHandler@563492b1 stateTo() completed. Socket state change success(updateWanted:CONNECT_FAILED ,before:BEING_CONNECT ,current:CONNECT_FAILED).
2018-05-18 10:00:34 INFO PinpointClientHandshaker@21550abf handshakeAbort() started.
2018-05-18 10:00:34 INFO PinpointClientHandshaker@21550abf unexpected state
2018-05-18 10:00:37 WARN try reconnect. connectAddress:DnsSocketAddressProvider{host='172.20.10.30', port=9994}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 initReconnect() started.
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 stateTo() completed. Socket state change success(updateWanted:BEING_CONNECT ,before:NONE ,current:BEING_CONNECT).
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 initReconnect() completed.
2018-05-18 10:00:37 INFO reconnect success DnsSocketAddressProvider{host='172.20.10.30', port=9994}, [id: 0xe90ae318, /172.20.10.32:5704 => /172.20.10.30:9994]
2018-05-18 10:00:37 WARN reconnectClientHandler:DefaultPinpointClientHandler@3ee5be65{channel=[id: 0xe90ae318, /172.20.10.32:5704 => /172.20.10.30:9994]state=SocketState(NONE->BEING_CONNECT)}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 channelConnected() started. channel:[id: 0xe90ae318, /172.20.10.32:5704 => /172.20.10.30:9994]
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 stateTo() completed. Socket state change success(updateWanted:CONNECTED ,before:BEING_CONNECT ,current:CONNECTED).
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 stateTo() completed. Socket state change success(updateWanted:RUN_WITHOUT_HANDSHAKE ,before:CONNECTED ,current:RUN_WITHOUT_HANDSHAKE).
2018-05-18 10:00:37 INFO PinpointClientHandshaker@34c43aa3 handshakeStart() started. channel:[id: 0xe90ae318, /172.20.10.32:5704 => /172.20.10.30:9994]
2018-05-18 10:00:37 INFO PinpointClientHandshaker@34c43aa3 do handshake(1/2147483647). channel:[id: 0xe90ae318, /172.20.10.32:5704 => /172.20.10.30:9994].
2018-05-18 10:00:37 INFO PinpointClientHandshaker@34c43aa3 handshakeStart() completed. channel:[id: 0xe90ae318, /172.20.10.32:5704 => /172.20.10.30:9994], data:{socketId=19, applicationName=test, startTimestamp=1526027326774, agentId=settlment, hostName=Hexindai-XX, supportServer=true, pid=6331, serviceType=1010, ip=fe80:0:0:0:98d9:3aff:fee6:e556%3, version=1.7.3, supportCommandList=[750, 730, 710, 740]}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 channelConnected() completed.
2018-05-18 10:00:37 INFO PinpointClientHandshaker@34c43aa3 handshakeComplete() started. responsePacket:ControlHandshakeResponsePacket{requestId=0, payloadLength=27}
2018-05-18 10:00:37 INFO PinpointClientHandshaker@34c43aa3 handshakeComplete() completed. handshake-response:{code=0, subCode=2}.
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 handleHandshakePacket() started. message:ControlHandshakeResponsePacket{requestId=0, payloadLength=27}
2018-05-18 10:00:37 INFO DefaultPinpointClientHandler@3ee5be65 stateTo() completed. Socket state change success(updateWanted:RUN_DUPLEX ,before:RUN_WITHOUT_HANDSHAKE ,current:RUN_DUPLEX).
2018-05-18 10:00:37 INFO [id: 0xe90ae318, /172.20.10.32:5704 => /172.20.10.30:9994] handleHandshakePacket() completed. code:DUPLEX_COMMUNICATION
2018-05-18 10:01:37 INFO PinpointClientHandshaker@34c43aa3 HandshakeJob completed.

@leogoing
Copy link
Author

collector log
grep '2018-05-18 10:07:5' apache-tomcat-7.0.82-1/logs/ -R
apache-tomcat-7.0.82-1/logs/catalina.out:2018-05-18 10:07:53 DEBUG Received TAgentStatBatch=TAgentStatBatch(agentId:msg, startTimestamp:1525921566817, agentStats:[TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609248283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:155958352, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020181634712411706, systemCpuLoad:0.022199798183652877), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609253283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:158750848, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.010219724067450179, systemCpuLoad:0.02401635155850792), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609258283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:158984752, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020090406830738324, systemCpuLoad:0.03164239075841286), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609263283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:159125616, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.001525165226232842, systemCpuLoad:0.022877478393492627), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609268283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:159250728, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020408163265306124, systemCpuLoad:0.015816326530612247), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609273283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:159482544, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.002554931016862545, systemCpuLoad:0.01788451711803781), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime())])
apache-tomcat-7.0.82-1/logs/catalina.out:2018-05-18 10:07:53 DEBUG Received TAgentStatBatch=TAgentStatBatch(agentId:msg, startTimestamp:1525921566817, agentStats:[TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609248283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:155958352, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020181634712411706, systemCpuLoad:0.022199798183652877), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609253283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:158750848, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.010219724067450179, systemCpuLoad:0.02401635155850792), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609258283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:158984752, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020090406830738324, systemCpuLoad:0.03164239075841286), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609263283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:159125616, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.001525165226232842, systemCpuLoad:0.022877478393492627), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609268283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:159250728, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.0020408163265306124, systemCpuLoad:0.015816326530612247), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime()), TAgentStat(agentId:msg, startTimestamp:1525921566817, timestamp:1526609273283, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:159482544, jvmMemoryHeapMax:1864368128, jvmMemoryNonHeapUsed:157613368, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:16157), cpuLoad:TCpuLoad(jvmCpuLoad:0.002554931016862545, systemCpuLoad:0.01788451711803781), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime())])
apache-tomcat-7.0.82-1/logs/catalina.out:2018-05-18 10:07:54 DEBUG Got ping response for sessionid: 0x100000742ef004e after 1ms
apache-tomcat-7.0.82-1/logs/catalina.out:2018-05-18 10:07:55 DEBUG Got ping response for sessionid: 0x100000742ef004d after 1ms
apache-tomcat-7.0.82-1/logs/catalina.out:2018-05-18 10:07:58 DEBUG Got ping response for sessionid: 0x100000742ef004f after 2ms

@leogoing
Copy link
Author

I have just contacted the distributed tracing system. I have no idea about these. Thank you very much for your reply.

@leogoing
Copy link
Author

I've been sitting there for a while.

@leogoing
Copy link
Author

I checked that their time should be the same.

@leogoing
Copy link
Author

ApplicationMapStatisticsCallee_Ver2, ApplicationMapStatisticsCaller_Ver2 is still empty

@Xylus
Copy link
Contributor

Xylus commented May 21, 2018

The agent log has some weird stuff going on - it seems to have logs for both agentId=msg and agentId=settlment. I'm not quite sure what's going on there, please provide a bit more detail on how your applications are set up along with the agent.

Also, the collector log you provided doesn't have any logs for transactions, so nothing should show up in the server map.

@leogoing
Copy link
Author

Yes, I have two agent.
I added this to the start shell in two application：
export CATALINA_OPTS="$CATALINA_OPTS -javaagent:/export/apm/pinpoint-agent/pinpoint-bootstrap-1.7.3.jar -Dpinpoint.agentId=settlment -Dpinpoint.applicationName=test"

Do you mean that I don't have transactions in my app? What does transaction mean? The database transaction or a complete request？

@Xylus
Copy link
Contributor

Xylus commented May 21, 2018

Are the agent ids same for the 2 applications? Note that agent ids must be globally unique so you will have to give different java processes different agent ids if this is the case.
Also, where is the agentId=msg coming from?

Regarding the transaction log, sorry, I should've been more clear - transaction as in a single, complete request (across multiple nodes if applicable) that shows up in the server map.
When a request hits an application the agent traces everything related to that request and sends it over to the collector. The collector then stores this data into hbase tables (including ApplicationMapStatisticsCallee_Ver2 and ApplicationMapStatisticsCaller_Ver2) and leaves a DEBUG log. Pinpoint web then reads this data from hbase to create the server map.
The collector log above is missing this.

@Xylus
Copy link
Contributor

Xylus commented May 21, 2018

To simplify the testing process, could you try the following?

  1. Stop all agents registered under test application name.
  2. Restart pinpoint collector and web.
  3. Start 1 application with pinpoint agent attached.
  4. Make sure the application you just started in step 2 shows up on the Web UI as a single node.
  5. Make a few requests to the application you started in step 2 and see if the server map (and the load charts) picks this up.

If the server map and the load charts still don't show anything, please attach the whole DEBUG log for the agent, collector and web so we can take a look at it.

@leogoing
Copy link
Author

Their ids are different, and I only show one of them. OK I'll try. Thank you very much

@nicechou
Copy link

Hello, I have the same problem. How did you solve it? thanks

@stale
Copy link

stale bot commented Aug 11, 2018

This issue/proposal has been automatically marked as stale because it hasn't had any recent activity. It will automatically be closed if no further activity occurs for 20days. If you think this should still be open, or the problem still persists, just pop a reply in the comments and one of the maintainers will (try!) to follow up. Thank you for your interest and contribution to the Pinpoint Community.

@stale stale bot added the stale label Aug 11, 2018
@NiLtheGazettE
Copy link

Hello, I have the same problem. How did you solve it? thanks

@stale stale bot removed the stale label Aug 30, 2018
@NiLtheGazettE
Copy link

@Xylus @leogoing

@Xylus
Copy link
Contributor

Xylus commented Aug 30, 2018

Hi @NiLtheGazettE
Please attach the agent, collector and web's DEBUG log that includes the requests not showing up on the server map so we can take a look.

@leogoing
Copy link
Author

Guys I've given up

@egdelgadillo egdelgadillo mentioned this issue Sep 26, 2018
Closed
@egdelgadillo
Copy link

I've got the same issue, but I've opened a new issue ( #4673 ) for the sake of order

@egdelgadillo
Copy link

I solved my issue. Check my #4673 post for you may find the solution there too

@evan886
Copy link

evan886 commented Oct 20, 2018

THX ,has solved it

@stale
Copy link

stale bot commented Nov 19, 2018

This issue/proposal has been automatically marked as stale because it hasn't had any recent activity. It will automatically be closed if no further activity occurs for 20days. If you think this should still be open, or the problem still persists, just pop a reply in the comments and one of the maintainers will (try!) to follow up. Thank you for your interest and contribution to the Pinpoint Community.

@stale stale bot added the stale label Nov 19, 2018
@stale stale bot closed this as completed Dec 9, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
question stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@evan886 @minwoo-jung @Xylus @egdelgadillo @leogoing @nicechou @NiLtheGazettE