search

kieker-monitoring / kieker

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

[KIEKER-465] Log replayer not working in realtime mode #1362

Closed rju closed 17 hours ago

rju commented 3 days ago

JIRA Issue: KIEKER-465 Log replayer not working in realtime mode Original Reporter: Andre van Hoorn

avanhoornavanhoorn-thinkpad:0:~/git_work/kieker.releases/1.5/kieker-1.5_binaries-zip/kieker-1.5 <master> $ bin/logReplay.sh -i examples/userguide/appendix-Sigar/testdata/kieker-20110511-10095928-UTC-avanhoorn-thinkpad-KIEKER-SINGLETON/ -k true -r true

340  INFO  [main] kieker.tools.logReplayer.RecordDelegationPlugin     - Ignoring records before Thu, 1 Jan 1970 00:00:00 +0000 (UTC)
341  INFO  [main] kieker.tools.logReplayer.RecordDelegationPlugin     - Ignoring records after Fri, 11 Apr 2262 23:47:16 +0000 (UTC)
346  INFO  [Thread-5] kieker.analysis.plugin.reader.filesystem.FSDirectoryReader     - < Loading /home/avanhoorn/git_work/kieker.releases/1.5/kieker-1.5_binaries-zip/kieker-1.5/examples/userguide/appendix-Sigar/testdata/kieker-20110511-10095928-UTC-avanhoorn-thinkpad-KIEKER-SINGLETON/kieker-20110511-101001633-UTC-Thread-1.dat
351  WARN  [Thread-4] kieker.analysis.plugin.AbstractPlugin     - Caught exception when sending data from kieker.analysis.plugin.reader.filesystem.FSReader: OutputPort monitoringRecords to kieker.tools.logReplayer.RealtimeReplayDistributor's InputPort inputMonitoringRecords
java.lang.reflect.InvocationTargetException
        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.reader.filesystem.FSReader.read(FSReader.java:105)
        at kieker.analysis.AnalysisController$1.run(AnalysisController.java:619)
        at java.lang.Thread.run(Thread.java:662)
Caused by: java.lang.IllegalStateException: Unable to connect readers and filters after starting analysis.
        at kieker.analysis.AnalysisController.connect(AnalysisController.java:413)
        at kieker.tools.logReplayer.RealtimeReplayWorker.initialize(RealtimeReplayWorker.java:64)
        at kieker.tools.logReplayer.RealtimeReplayDistributor.inputMonitoringRecords(RealtimeReplayDistributor.java:145)
        ... 8 more
353  WARN  [Thread-4] kieker.analysis.plugin.AbstractPlugin     - Caught exception when sending data from kieker.analysis.plugin.reader.filesystem.FSReader: OutputPort monitoringRecords to kieker.tools.logReplayer.RealtimeReplayDistributor's InputPort inputMonitoringRecords
java.lang.reflect.InvocationTargetException
        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.reader.filesystem.FSReader.read(FSReader.java:105)
        at kieker.analysis.AnalysisController$1.run(AnalysisController.java:619)
        at java.lang.Thread.run(Thread.java:662)
rju commented 2 days ago

author André van Hoorn -- Fri, 13 Apr 2012 09:04:21 +0200

Fixed hacked in 782e16782135798e5ac25a696ab3defdc25da8a5 but rt replayer must be refactored anyway ( KIEKER-694 Done ) --- currently, it is a mess ....

avanhoornavanhoorn-thinkpad:0:~/git_work/kieker <master> $ bin/logReplay.sh -i examples/userguide/appendix-Sigar/testdata/kieker-20110511-10095928-UTC-avanhoorn-thinkpad-KIEKER-SINGLETON/ -k true -r true

0    INFO  [main] kieker.tools.logReplayer.FilesystemLogReplayerStarter     - Keeping original logging timestamps: true
19   INFO  [main] kieker.tools.logReplayer.FilesystemLogReplayerStarter     - inputDirs: examples/userguide/appendix-Sigar/testdata/kieker-20110511-10095928-UTC-avanhoorn-thinkpad-KIEKER-SINGLETON/
20   INFO  [main] kieker.tools.logReplayer.FilesystemLogReplayerStarter     - Replaying in realtime mode
20   INFO  [main] kieker.tools.logReplayer.FilesystemLogReplayerStarter     - Using 1 realtime worker thread
20   INFO  [main] kieker.tools.logReplayer.FilesystemLogReplayerStarter     - Replaying log data in real time
87   INFO  [main] kieker.monitoring.core.controller.MonitoringController     - Current State of kieker.monitoring (1.5-SNAPSHOT) Status: 'enabled'
        Name: 'KIEKER'; Hostname: 'avanhoorn-thinkpad'; experimentID: '1'
JMXController: JMX disabled
RegistryController: 0 strings registered.
TimeSource: 'kieker.monitoring.timer.SystemNanoTimer'
        Time in nanoseconds (with nanoseconds precision) since Thu Jan 01 01:00:00 CET 1970'
WriterController:
        Number of Inserts: '0'
        Automatic assignment of logging timestamps: 'false'
Writer: 'kieker.monitoring.writer.filesystem.AsyncFsWriter'
        Configuration:
                kieker.monitoring.writer.filesystem.AsyncFsWriter.QueueFullBehavior='0'
                kieker.monitoring.writer.filesystem.AsyncFsWriter.flush='true'
                kieker.monitoring.writer.filesystem.AsyncFsWriter.QueueSize='10000'
                kieker.monitoring.writer.filesystem.AsyncFsWriter.customStoragePath='.'
                kieker.monitoring.writer.filesystem.AsyncFsWriter.MaxShutdownDelay='-1'
                kieker.monitoring.writer.filesystem.AsyncFsWriter.storeInJavaIoTmpdir='true'
                kieker.monitoring.writer.filesystem.AsyncFsWriter.maxEntriesInFile='25000'
        Records lost: 0
        Writer Threads (1): 
                Finished: 'false'; Writing to Directory: '/tmp/kieker-20120413-064306156-UTC-avanhoorn-thinkpad-KIEKER'
Sampling Controller: Periodic Sensor available: Current Poolsize: '0'; Scheduled Tasks: '0'

349  INFO  [main] kieker.tools.logReplayer.RecordDelegationPlugin     - Ignoring records before Thu, 1 Jan 1970 00:00:00 +0000 (UTC)
350  INFO  [main] kieker.tools.logReplayer.RecordDelegationPlugin     - Ignoring records after Fri, 11 Apr 2262 23:47:16 +0000 (UTC)
355  INFO  [Thread-5] kieker.analysis.plugin.reader.filesystem.FSDirectoryReader     - < Loading /home/avanhoorn/git_work/kieker/examples/userguide/appendix-Sigar/testdata/kieker-20110511-10095928-UTC-avanhoorn-thinkpad-KIEKER-SINGLETON/kieker-20110511-101001633-UTC-Thread-1.dat
367  INFO  [Thread-3]    kieker.analysis.AnalysisController     - Terminating analysis.
367  INFO  [Thread-3] kieker.analysis.plugin.reader.filesystem.FSReader     - Shutting down reader.
367  INFO  [Thread-3] kieker.tools.logReplayer.RealtimeReplayDistributor     - Will terminate in 26588421791nsecs from now
26956 INFO  [main]    kieker.analysis.AnalysisController     - Terminating analysis.
26957 INFO  [Thread-2] kieker.monitoring.core.controller.MonitoringController     - ShutdownHook notifies controller to initiate shutdown
26957 INFO  [Thread-2] kieker.monitoring.core.controller.MonitoringController     - Shutting down Monitoring Controller (KIEKER)
26957 INFO  [Thread-2] kieker.monitoring.writer.AbstractAsyncWriter     - Shutting down writers.
26957 INFO  [Thread-2] kieker.monitoring.writer.AbstractAsyncWriter     - Writer shutdown complete.

Deviation in order of records (which is OK).

avanhoornavanhoorn-thinkpad:1:~/git_work/kieker <master> $ diff -C 3 /tmp/kieker-20120413-064306156-UTC-avanhoorn-thinkpad-KIEKER/kieker-20120413-064308446-UTC--000-Thread-1.dat examples/userguide/appendix-Sigar/testdata/kieker-20110511-10095928-UTC-avanhoorn-thinkpad-KIEKER-SINGLETON/kieker-20110511-101001633-UTC-Thread-1.dat 
*** /tmp/kieker-20120413-064306156-UTC-avanhoorn-thinkpad-KIEKER/kieker-20120413-064308446-UTC--000-Thread-1.dat        2012-04-13 08:43:32.939576900 +0200
--- examples/userguide/appendix-Sigar/testdata/kieker-20110511-10095928-UTC-avanhoorn-thinkpad-KIEKER-SINGLETON/kieker-20110511-101001633-UTC-Thread-1.dat      2012-01-22 13:46:07.581534534 +0100
***************
*** 1,5 ****
- $0;1305108601633259603;1305108601633248708;avanhoorn-thinkpad;1;0.0;0.0;0.0;0.0;0.0;0.0;1.0
  $0;1305108601633129838;1305108601632983451;avanhoorn-thinkpad;0;0.0;0.0;0.0;0.0;0.0;0.0;1.0
  $1;1305108601636322982;1305108601636245458;avanhoorn-thinkpad;4046708736;757145600;3289563136;3999260672;0;3999260672
  $0;1305108606129254690;1305108606129235693;avanhoorn-thinkpad;0;0.004454342984409799;0.028953229398663696;0.0200445434298441;0.0;0.0;0.05345211581291759;0.9465478841870824
  $0;1305108606129294430;1305108606129284861;avanhoorn-thinkpad;1;0.006535947712418301;0.006535947712418301;0.0;0.0;0.0;0.013071895424836602;0.9869281045751634
--- 1,5 ----
  $0;1305108601633129838;1305108601632983451;avanhoorn-thinkpad;0;0.0;0.0;0.0;0.0;0.0;0.0;1.0
+ $0;1305108601633259603;1305108601633248708;avanhoorn-thinkpad;1;0.0;0.0;0.0;0.0;0.0;0.0;1.0
  $1;1305108601636322982;1305108601636245458;avanhoorn-thinkpad;4046708736;757145600;3289563136;3999260672;0;3999260672
  $0;1305108606129254690;1305108606129235693;avanhoorn-thinkpad;0;0.004454342984409799;0.028953229398663696;0.0200445434298441;0.0;0.0;0.05345211581291759;0.9465478841870824
  $0;1305108606129294430;1305108606129284861;avanhoorn-thinkpad;1;0.006535947712418301;0.006535947712418301;0.0;0.0;0.0;0.013071895424836602;0.9869281045751634
rju commented 2 days ago

author André van Hoorn -- Fri, 13 Apr 2012 09:04:43 +0200

Pushed to master; needs to be cherrypicked to 1.5

rju commented 2 days ago

author André van Hoorn -- Fri, 13 Apr 2012 09:29:06 +0200

Merged master into 1.5 in e33497384ad712ba0dae6b3117acc8b3e2c4716b

rju commented 2 days ago

author André van Hoorn -- Fri, 13 Apr 2012 10:22:43 +0200

Also added a fix for negative scheduling times in 53e8d1e64c6765f4cdf909933210b4626fd090d1