kieker-monitoring / kieker

Kieker's main repository
Apache License 2.0
70 stars 41 forks source link

[KIEKER-821] trace-analysis tool dropping traces when using multiple plots/prints #1071

Open rju opened 2 weeks ago

rju commented 2 weeks ago

JIRA Issue: KIEKER-821 trace-analysis tool dropping traces when using multiple plots/prints Original Reporter: Nis Wechselberg


When analyzing the attached trace with all availible plot/print options activated, the trace-analysis tool only accepts 2 or 3 traces and doesn't generate the system-overview.htm.
When restricting the tool to only single plots or prints it uses all 6 traces.

Checklist:

rju commented 2 weeks ago

author 557058:547c6d61-d075-40d8-85a2-0fec50bae1f9 unknown Jira user -- Fri, 8 Mar 2013 10:56:11 +0100

Attachment kieker-eprints-trace-part1.tar.gz has been added with description: Kieker Trace Part1

rju commented 2 weeks ago

author 557058:547c6d61-d075-40d8-85a2-0fec50bae1f9 unknown Jira user -- Fri, 8 Mar 2013 10:56:34 +0100

Attachment kieker-eprints-trace-part2.tar.gz has been added with description: Kieker Trace Part 2

rju commented 2 weeks ago

author André van Hoorn -- Fri, 8 Mar 2013 11:11:00 +0100

Could you please provide the command line parameters, as well?

rju commented 2 weeks ago

author 557058:547c6d61-d075-40d8-85a2-0fec50bae1f9 unknown Jira user -- Fri, 8 Mar 2013 13:56:44 +0100

Behaviour seems to vary between machines. My Ubuntu 12.04 VirtualBox keeps on dropping traces reagrdless of options.
Will add logs from my Windows machine at home when I'm back there.

rju commented 2 weeks ago

author 557058:8c5f237f-11c8-4d84-9483-af213ff5f946 unknown Jira user -- Sat, 9 Mar 2013 21:19:59 +0100

Command Line:

PS C:\Users\eNBeWe\Desktop\trace-analyse\kieker-1.7-SNAPSHOT\bin> .\trace-analysis.bat -i ..\..\kieker-eprints-geomar-traces1 -o ..\..\test --plot-Call-Trees
[...]
# Plugin:
Wrote HTML output of system model to file 'C:\Users\eNBeWe\Desktop\trace-analyse\test\system-entities.html'
#
# Plugin: Trace call trees
Trace processing summary: 6 total; 6 succeeded; 0 failed.
Wrote 6 call trees to files with name pattern 'C:\Users\eNBeWe\Desktop\trace-analyse\test\callTree-<traceId>.dot'
Dot files can be converted using the dot tool
Example: dot -T svg C:\Users\eNBeWe\Desktop\trace-analyse\test\callTree-30170.dot > C:\Users\eNBeWe\Desktop\trace-analyse\test\callTree-30170.svg
#
# Plugin: Trace reconstruction (execution records -> execution traces)
Trace processing summary: 0 total; 0 succeeded; 0 failed.
#
# Plugin: Trace reconstruction (event records -> event record traces)
Trace processing summary: 6 total; 6 succeeded; 0 failed.
#
# Plugin: Trace reconstruction (event record traces -> execution traces)
Trace processing summary: 6 total; 6 succeeded; 0 failed.
PS C:\Users\eNBeWe\Desktop\trace-analyse\kieker-1.7-SNAPSHOT\bin> .\trace-analysis.bat -i ..\..\kieker-eprints-geomar-traces1 -o ..\..\test --plot-Call-Trees --plot-Aggregated-Assembly-Call-
Tree --print-Message-Traces --print-Execution-Traces --print-invalid-Execution-Traces --print-Deployment-Equivalence-Classes --print-Assembly-Equivalence-Classes
[...]
#
# Plugin:
Failed to write HTML output of system model to file '../../test/system-entities.html'

#
# Plugin: Trace equivalence class filter (deployment mode)
Trace processing summary: 4 total; 4 succeeded; 0 failed.

#
# Plugin: Trace equivalence class filter (assembly mode)
Trace processing summary: 4 total; 4 succeeded; 0 failed.

#
# Plugin: Print message traces
Trace processing summary: 3 total; 3 succeeded; 0 failed.
Wrote 3 traces to file 'C:\Users\eNBeWe\Desktop\trace-analyse\test\messageTraces.txt'

#
# Plugin: Print execution traces
Trace processing summary: 4 total; 4 succeeded; 0 failed.
Wrote 4 execution traces to file 'C:\Users\eNBeWe\Desktop\trace-analyse\test\executionTraces.txt'

#
# Plugin: Print invalid execution traces
Trace processing summary: 0 total; 0 succeeded; 0 failed.
Wrote 0 execution trace artifact to file 'C:\Users\eNBeWe\Desktop\trace-analyse\test\invalidTraceArtifacts.txt'

#
# Plugin: Trace call trees
Trace processing summary: 3 total; 3 succeeded; 0 failed.
Wrote 3 call trees to files with name pattern 'C:\Users\eNBeWe\Desktop\trace-analyse\test\callTree-<traceId>.dot'
Dot files can be converted using the dot tool
Example: dot -T svg C:\Users\eNBeWe\Desktop\trace-analyse\test\callTree-30165.dot > C:\Users\eNBeWe\Desktop\trace-analyse\test\callTree-30165.svg

#
# Plugin: Aggregated call tree (assembly level)
Trace processing summary: 3 total; 3 succeeded; 0 failed.
Saved 0 call tree

#
# Plugin: Trace equivalence report
Wrote 4 equivalence classes to file 'C:\Users\eNBeWe\Desktop\trace-analyse\test\traceDeploymentEquivClasses.txt'

#
# Plugin: Trace equivalence report
Wrote 4 equivalence classes to file 'C:\Users\eNBeWe\Desktop\trace-analyse\test\traceAssemblyEquivClasses.txt'

#
# Plugin: Trace reconstruction (execution records -> execution traces)
Trace processing summary: 0 total; 0 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event records -> event record traces)
Trace processing summary: 4 total; 4 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event record traces -> execution traces)
Trace processing summary: 3 total; 3 succeeded; 0 failed.

System Specs:
Intel(R) Core(TM)2 Quad CPU Q6600 2.40GHz
4,00 GB RAM
Windows 7 Professional 64-Bit

Kieker Snapshot downloaded between 4th and 7th.

rju commented 2 weeks ago

author André van Hoorn -- Fri, 12 Apr 2013 23:35:15 +0200

Could reproduce the problem. The log reveals that the reason is a java.lang.OutOfMemoryError:

avhAndrè van Hoorn-ThinkPad-RSS:0:~/git_work/kieker <master> $ bin/trace-analysis.sh -i /tmp/807-eprints-traces --plot-Call-Trees -o tmp/ -p 1-
#
# Configuration
--inputdirs: /tmp/807-eprints-traces
--outputdir: tmp//
--output-filename-prefix: 1-
--plot-Deployment-Sequence-Diagrams: false
--plot-Assembly-Sequence-Diagrams: false
--plot-Deployment-Component-Dependency-Graph: false
--plot-Assembly-Component-Dependency-Graph: false
--plot-Container-Dependency-Graph: false
--plot-Deployment-Operation-Dependency-Graph: false
--plot-Assembly-Operation-Dependency-Graph: false
--plot-Aggregated-Deployment-Call-Tree: false
--plot-Aggregated-Assembly-Call-Tree: false
--plot-Call-Trees: true
--print-Message-Traces: false
--print-Execution-Traces: false
--print-invalid-Execution-Traces: false
--print-Deployment-Equivalence-Classes: false
--print-Assembly-Equivalence-Classes: false
--select-traces: <select all>
--ignore-invalid-traces: false
--max-trace-duration: 600000 ms
--ignore-executions-before-date: Thu, 1 Jan 1970 00:00:00 +0000 (UTC) (Thu, 1 Jan 1970 01:00:00 +0100 (local time))
--ignore-executions-after-date: Fri, 11 Apr 2262 23:47:16 +0000 (UTC) (Sat, 12 Apr 2262 01:47:16 +0200 (local time))
--short-labels: false
--include-self-loops: false
--traceColoring: 
--addDescriptions: 

#
# Plugin: SystemModel2FileFilter-6
Failed to write HTML output of system model to file 'tmp/1-system-entities.html'

#
# Plugin: Trace call trees
Trace processing summary: 3 total; 3 succeeded; 0 failed.
Wrote 3 call trees to files with name pattern '/home/avh/git_work/kieker/tmp/1-callTree-<traceId>.dot'
Dot files can be converted using the dot tool
Example: dot -T svg /home/avh/git_work/kieker/tmp/1-callTree-30165.dot > /home/avh/git_work/kieker/tmp/1-callTree-30165.svg

#
# Plugin: Trace reconstruction (execution records -> execution traces)
Trace processing summary: 0 total; 0 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event records -> event record traces)
Trace processing summary: 4 total; 4 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event record traces -> execution traces)
Trace processing summary: 3 total; 3 succeeded; 0 failed.

See 'kieker.log' for details

real    1m43.627s
user    2m3.040s
sys     0m13.041s
SEVERE: Exception while reading on Reader 'FSReader-2' (FSReader).
java.lang.OutOfMemoryError: Java heap space
        at java.util.concurrent.ConcurrentHashMap.<init>(ConcurrentHashMap.java:613)
        at java.util.concurrent.ConcurrentHashMap.<init>(ConcurrentHashMap.java:652)
        at kieker.tools.traceAnalysis.filter.visualization.graph.AbstractVertex.<init>(AbstractVertex.java:40)
        at kieker.tools.traceAnalysis.filter.visualization.callTree.AbstractCallTreeNode.<init>(AbstractCallTreeNode.java:62)
        at kieker.tools.traceAnalysis.filter.visualization.callTree.TraceCallTreeNode.<init>(TraceCallTreeNode.java:48)
        at kieker.tools.traceAnalysis.filter.visualization.callTree.TraceCallTreeNode.newCall(TraceCallTreeNode.java:55)
        at kieker.tools.traceAnalysis.filter.visualization.callTree.TraceCallTreeNode.newCall(TraceCallTreeNode.java:30)
        at kieker.tools.traceAnalysis.filter.visualization.callTree.AbstractCallTreeFilter.addTraceToTree(AbstractCallTreeFilter.java:305)
        at kieker.tools.traceAnalysis.filter.visualization.callTree.AbstractCallTreeFilter.writeDotForMessageTrace(AbstractCallTreeFilter.java:323)
        at kieker.tools.traceAnalysis.filter.visualization.callTree.TraceCallTreeFilter.inputMessageTraces(TraceCallTreeFilter.java:144)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at kieker.analysis.plugin.AbstractPlugin.deliver(AbstractPlugin.java:208)
        at kieker.tools.traceAnalysis.filter.flow.TraceEventRecords2ExecutionAndMessageTraceFilter.inputTraceEvents(TraceEventRecords2ExecutionAndMessageTraceFilter.java:190)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at kieker.analysis.plugin.AbstractPlugin.deliver(AbstractPlugin.java:208)
        at kieker.analysis.plugin.filter.flow.EventRecordTraceReconstructionFilter.newEvent(EventRecordTraceReconstructionFilter.java:217)
        at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at kieker.analysis.plugin.AbstractPlugin.deliver(AbstractPlugin.java:208)
        at kieker.analysis.plugin.filter.select.TraceIdFilter.inputTraceEvent(TraceIdFilter.java:161)
        at kieker.analysis.plugin.filter.select.TraceIdFilter.inputCombined(TraceIdFilter.java:136)
        at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at kieker.analysis.plugin.AbstractPlugin.deliver(AbstractPlugin.java:208)
rju commented 2 weeks ago

author André van Hoorn -- Fri, 12 Apr 2013 23:46:20 +0200

Increased memory and now it works:

avhAndrè van Hoorn-ThinkPad-RSS:0:~/git_work/kieker <master> $ git diff bin/trace-analysis.sh
diff --git a/bin/trace-analysis.sh b/bin/trace-analysis.sh
index 475ef7f..ddea382 100755
--- a/bin/trace-analysis.sh
+++ b/bin/trace-analysis.sh
 -7,7 +7,7 

 BINDIR=$(cd "$(dirname "$0")"; pwd)/

-JAVAARGS="-Dkieker.common.logging.Log=JDK -Djava.util.logging.config.file=${BINDIR}/logging.properties -Xms56m -Xmx1024m"
+JAVAARGS="-Dkieker.common.logging.Log=JDK -Djava.util.logging.config.file=${BINDIR}/logging.properties -Xms56m -Xmx4024m"
 MAINCLASSNAME=kieker.tools.traceAnalysis.TraceAnalysisTool
 CLASSPATH=$(ls "${BINDIR}/../lib/"*.jar | tr "\n" ":")$(ls "${BINDIR}/../dist/"*.jar | tr "\n" ":")${BINDIR}
avhAndrè van Hoorn-ThinkPad-RSS:0:~/git_work/kieker <master> $ bin/trace-analysis.sh -i /tmp/807-eprints-traces --plot-Call-Trees -o tmp/ -p 1-
#
# Configuration
--inputdirs: /tmp/807-eprints-traces
--outputdir: tmp//
--output-filename-prefix: 1-
--plot-Deployment-Sequence-Diagrams: false
--plot-Assembly-Sequence-Diagrams: false
--plot-Deployment-Component-Dependency-Graph: false
--plot-Assembly-Component-Dependency-Graph: false
--plot-Container-Dependency-Graph: false
--plot-Deployment-Operation-Dependency-Graph: false
--plot-Assembly-Operation-Dependency-Graph: false
--plot-Aggregated-Deployment-Call-Tree: false
--plot-Aggregated-Assembly-Call-Tree: false
--plot-Call-Trees: true
--print-Message-Traces: false
--print-Execution-Traces: false
--print-invalid-Execution-Traces: false
--print-Deployment-Equivalence-Classes: false
--print-Assembly-Equivalence-Classes: false
--select-traces: <select all>
--ignore-invalid-traces: false
--max-trace-duration: 600000 ms
--ignore-executions-before-date: Thu, 1 Jan 1970 00:00:00 +0000 (UTC) (Thu, 1 Jan 1970 01:00:00 +0100 (local time))
--ignore-executions-after-date: Fri, 11 Apr 2262 23:47:16 +0000 (UTC) (Sat, 12 Apr 2262 01:47:16 +0200 (local time))
--short-labels: false
--include-self-loops: false
--traceColoring: 
--addDescriptions: 

#
# Plugin: SystemModel2FileFilter-6
Wrote HTML output of system model to file '/home/avh/git_work/kieker/tmp/1-system-entities.html'

#
# Plugin: Trace call trees
Trace processing summary: 6 total; 6 succeeded; 0 failed.
Wrote 6 call trees to files with name pattern '/home/avh/git_work/kieker/tmp/1-callTree-<traceId>.dot'
Dot files can be converted using the dot tool
Example: dot -T svg /home/avh/git_work/kieker/tmp/1-callTree-30170.dot > /home/avh/git_work/kieker/tmp/1-callTree-30170.svg

#
# Plugin: Trace reconstruction (execution records -> execution traces)
Trace processing summary: 0 total; 0 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event records -> event record traces)
Trace processing summary: 6 total; 6 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event record traces -> execution traces)
Trace processing summary: 6 total; 6 succeeded; 0 failed.

See 'kieker.log' for details

real    3m42.048s
user    4m31.333s
sys     0m37.982s
rju commented 2 weeks ago

author André van Hoorn -- Fri, 12 Apr 2013 23:55:13 +0200

Just to add to this: Also works with the longer list of options (with the increased memory allocation):

avhAndrè van Hoorn-ThinkPad-RSS:1:~/git_work/kieker <master> $ bin/trace-analysis.sh -i /tmp/807-eprints-traces -o tmp/ -p 1- --plot-Call-Trees --plot-Aggregated-Assembly-Call-Tree --print-Message-Traces --print-Execution-Traces --print-invalid-Execution-Traces --print-Deployment-Equivalence-Classes --print-Assembly-Equivalence-Classes
#
# Configuration
--inputdirs: /tmp/807-eprints-traces
--outputdir: tmp//
--output-filename-prefix: 1-
--plot-Deployment-Sequence-Diagrams: false
--plot-Assembly-Sequence-Diagrams: false
--plot-Deployment-Component-Dependency-Graph: false
--plot-Assembly-Component-Dependency-Graph: false
--plot-Container-Dependency-Graph: false
--plot-Deployment-Operation-Dependency-Graph: false
--plot-Assembly-Operation-Dependency-Graph: false
--plot-Aggregated-Deployment-Call-Tree: false
--plot-Aggregated-Assembly-Call-Tree: true
--plot-Call-Trees: true
--print-Message-Traces: true
--print-Execution-Traces: true
--print-invalid-Execution-Traces: true
--print-Deployment-Equivalence-Classes: true
--print-Assembly-Equivalence-Classes: true
--select-traces: <select all>
--ignore-invalid-traces: false
--max-trace-duration: 600000 ms
--ignore-executions-before-date: Thu, 1 Jan 1970 00:00:00 +0000 (UTC) (Thu, 1 Jan 1970 01:00:00 +0100 (local time))
--ignore-executions-after-date: Fri, 11 Apr 2262 23:47:16 +0000 (UTC) (Sat, 12 Apr 2262 01:47:16 +0200 (local time))
--short-labels: false
--include-self-loops: false
--traceColoring: 
--addDescriptions: 

#
# Plugin: Aggregated call tree (assembly level)
Wrote call tree to file '/home/avh/git_work/kieker/tmp/1-aggregatedAssemblyCallTree.dot'
Dot file can be converted using the dot tool
Example: dot -T svg /home/avh/git_work/kieker/tmp/1-aggregatedAssemblyCallTree.dot > /home/avh/git_work/kieker/tmp/1-aggregatedAssemblyCallTree.dot.svg

#
# Plugin: SystemModel2FileFilter-6
Wrote HTML output of system model to file '/home/avh/git_work/kieker/tmp/1-system-entities.html'

#
# Plugin: Trace equivalence class filter (deployment mode)
Trace processing summary: 6 total; 6 succeeded; 0 failed.

#
# Plugin: Trace equivalence class filter (assembly mode)
Trace processing summary: 6 total; 6 succeeded; 0 failed.

#
# Plugin: Print message traces
Trace processing summary: 6 total; 6 succeeded; 0 failed.
Wrote 6 traces to file '/home/avh/git_work/kieker/tmp/1-messageTraces.txt'

#
# Plugin: Print execution traces
Trace processing summary: 6 total; 6 succeeded; 0 failed.
Wrote 6 execution traces to file '/home/avh/git_work/kieker/tmp/1-executionTraces.txt'

#
# Plugin: Print invalid execution traces
Trace processing summary: 0 total; 0 succeeded; 0 failed.
Wrote 0 execution trace artifact to file '/home/avh/git_work/kieker/tmp/1-invalidTraceArtifacts.txt'

#
# Plugin: Trace call trees
Trace processing summary: 6 total; 6 succeeded; 0 failed.
Wrote 6 call trees to files with name pattern '/home/avh/git_work/kieker/tmp/1-callTree-<traceId>.dot'
Dot files can be converted using the dot tool
Example: dot -T svg /home/avh/git_work/kieker/tmp/1-callTree-30170.dot > /home/avh/git_work/kieker/tmp/1-callTree-30170.svg

#
# Plugin: Aggregated call tree (assembly level)
Trace processing summary: 6 total; 6 succeeded; 0 failed.
Saved 1 call tree

#
# Plugin: Trace equivalence report
Wrote 6 equivalence classes to file '/home/avh/git_work/kieker/tmp/1-traceDeploymentEquivClasses.txt'

#
# Plugin: Trace equivalence report
Wrote 6 equivalence classes to file '/home/avh/git_work/kieker/tmp/1-traceAssemblyEquivClasses.txt'

#
# Plugin: Trace reconstruction (execution records -> execution traces)
Trace processing summary: 0 total; 0 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event records -> event record traces)
Trace processing summary: 6 total; 6 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event record traces -> execution traces)
Trace processing summary: 6 total; 6 succeeded; 0 failed.

See 'kieker.log' for details

real    4m59.104s
user    5m33.901s
sys     0m39.814s