I have an issue with a Jmeter scenario where my dashboard report is getting a start time of Start Time "1/1/70, 12:00 AM"
The end time is working fine
End Time "12/11/21, 10:04 PM"
In the same script, If I disable the thread group hitting this issue and run another thread group, the start time is ok. This leads me to think it's a problem with the timing in this particular thread group rather than a problem with my JM props.
I am attempting to simulate long (1 hour +) websocket sessions with a start/pingpong/end.
Runtime controller with a sub loop controller running the websocket ping/pong in the middle.
The ping/pong uses a runtime controller where duration = rampup + full load time.
The pingpong loop controller runs every 60 sec for the duration of the thread rampup + full load.
The overall threadgroup duration is (rampup x 2) + full load.
As far as I can tell all of this adds up to long running threads doing the needed txns, while keeping open websocket connections, and running as expected.
I set DEBUG for Report logging and nothing unusual is jumping out at me as a cause. (Those relevant logs below)
The only Report related JMeter props that I am customizing at runtime or otherwise are the following:
-Jjmeter.reportgenerator.overall_granularity=$REPORTGRAN\
-Jjmeter.reportgenerator.report_title=$TESTRUNNAME$STARTTIMEJM\
Here are the relevant report props from the JM log:
2021-12-11 20:53:56,036 DEBUG o.a.j.r.c.ReportGeneratorConfiguration: Report generator properties loading
2021-12-11 20:53:56,041 DEBUG o.a.j.r.c.ReportGeneratorConfiguration: Loading properties:
...
2021-12-11 20:53:56,091 DEBUG o.a.j.r.c.ReportGeneratorConfiguration: Use 'TG10_<REDACTED>_10T-20211211-2053' value for optional property 'jmeter.reportgenerator.report_title'
2021-12-11 20:53:56,091 INFO o.a.j.r.c.ReportGeneratorConfiguration: Property 'jmeter.reportgenerator.start_date' not found, using default value 'null' instead.
2021-12-11 20:53:56,091 INFO o.a.j.r.c.ReportGeneratorConfiguration: Property 'jmeter.reportgenerator.end_date' not found, using default value 'null' instead.
2021-12-11 20:53:56,091 INFO o.a.j.r.c.ReportGeneratorConfiguration: Property 'jmeter.reportgenerator.date_format' not found, using default value 'null' instead.
2021-12-11 20:53:56,112 INFO o.a.j.r.c.ReportGeneratorConfiguration: Will use date range start date: null, end date: null
At the end of the test run log, everything seems to go off without an obvious error. The report is fine aside from the Start time being 1970.
2021-12-11 22:04:17,129 DEBUG o.a.j.r.d.ReportGenerator: Start report generation
2021-12-11 22:04:17,147 INFO o.a.j.r.p.NormalizerSampleConsumer: Using format, 'ms', to parse timeStamp field
2021-12-11 22:04:17,177 DEBUG o.a.j.r.d.ReportGenerator: Start samples processing
2021-12-11 22:04:18,554 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.AggregateConsumer#stopProducing(): beginDate produced 0 samples
2021-12-11 22:04:18,554 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.AggregateConsumer#stopProducing(): endDate produced 0 samples
2021-12-11 22:04:18,557 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.ApdexSummaryConsumer#stopProducing(): apdexSummary produced 0 samples
2021-12-11 22:04:18,557 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.RequestsSummaryConsumer#stopProducing(): requestsSummary produced 0 samples
2021-12-11 22:04:18,583 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.StatisticsSummaryConsumer#stopProducing(): statisticsSummary produced 0 samples
2021-12-11 22:04:18,585 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.Top5ErrorsBySamplerConsumer#stopProducing(): top5ErrorsBySampler produced 0 samples
2021-12-11 22:04:18,585 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.ErrorsSummaryConsumer#stopProducing(): errorsSummary produced 0 samples
2021-12-11 22:04:18,585 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.HitsPerSecondGraphConsumer#stopProducing(): hitsPerSecond produced 0 samples
2021-12-11 22:04:18,802 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.LatencyVSRequestGraphConsumer#stopProducing(): latencyVsRequest produced 0 samples
2021-12-11 22:04:18,804 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.SyntheticResponseTimeDistributionGraphConsumer#stopProducing(): syntheticResponseTimeDistribution produced 0 samples
2021-12-11 22:04:18,804 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.BytesThroughputGraphConsumer#stopProducing(): bytesThroughputOverTime produced 0 samples
2021-12-11 22:04:18,805 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.CodesPerSecondGraphConsumer#stopProducing(): codesPerSecond produced 0 samples
2021-12-11 22:04:19,016 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.ResponseTimeVSRequestGraphConsumer#stopProducing(): responseTimeVsRequest produced 0 samples
2021-12-11 22:04:19,018 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.FilterConsumer#stopProducing(): startIntervalControlerFilter produced 134253 samples
2021-12-11 22:04:19,018 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.TotalTPSGraphConsumer#stopProducing(): totalTPS produced 0 samples
2021-12-11 22:04:19,018 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.ActiveThreadsGraphConsumer#stopProducing(): activeThreadsOverTime produced 0 samples
2021-12-11 22:04:19,018 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.TimeVSThreadGraphConsumer#stopProducing(): timeVsThreads produced 0 samples
2021-12-11 22:04:19,022 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.ResponseTimeDistributionGraphConsumer#stopProducing(): responseTimeDistribution produced 0 samples
2021-12-11 22:04:19,022 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.TransactionsPerSecondGraphConsumer#stopProducing(): transactionsPerSecond produced 0 samples
2021-12-11 22:04:19,023 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.ResponseTimePercentilesGraphConsumer#stopProducing(): responseTimePercentiles produced 0 samples
2021-12-11 22:04:19,028 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.ResponseTimePercentilesOverTimeGraphConsumer#stopProducing(): responseTimePercentilesOverTime produced 0 samples
2021-12-11 22:04:19,038 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.ResponseTimeOverTimeGraphConsumer#stopProducing(): responseTimesOverTime produced 0 samples
2021-12-11 22:04:19,038 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.ConnectTimeOverTimeGraphConsumer#stopProducing(): connectTimeOverTime produced 0 samples
2021-12-11 22:04:19,038 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.graph.impl.LatencyOverTimeGraphConsumer#stopProducing(): latenciesOverTime produced 0 samples
2021-12-11 22:04:19,039 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.FilterConsumer#stopProducing(): nameFilter produced 287685 samples
2021-12-11 22:04:19,039 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.FilterConsumer#stopProducing(): dateRangeFilter produced 57537 samples
2021-12-11 22:04:19,039 INFO o.a.j.r.p.AbstractSampleConsumer: class org.apache.jmeter.report.processor.NormalizerSampleConsumer#stopProducing(): normalizer produced 19179 samples
2021-12-11 22:04:19,039 INFO o.a.j.r.p.CsvFileSampleSource: produce(): 19179 samples produced in 1s 862 ms on channel 0
2021-12-11 22:04:19,039 DEBUG o.a.j.r.d.ReportGenerator: End of samples processing
2021-12-11 22:04:19,039 DEBUG o.a.j.r.d.ReportGenerator: Start data exporting
2021-12-11 22:04:19,039 INFO o.a.j.r.d.ReportGenerator: Exporting data using exporter:'json' of className:'org.apache.jmeter.report.dashboard.JsonExporter'
2021-12-11 22:04:19,198 INFO o.a.j.r.d.JsonExporter: Found data for consumer statisticsSummary in context
2021-12-11 22:04:19,198 INFO o.a.j.r.d.JsonExporter: Creating statistics for overall
2021-12-11 22:04:19,198 DEBUG o.a.j.r.d.JsonExporter: Creating statistics for result data:MapResultData [map={data=ListResultData [items=[ValueResultData [value=Total], ValueResultData [value=19179], ValueResultData [value=306], ValueResultData [value=1.5954950727358048], ValueResultData [value=190.9874341727929], ValueResultData [value=0], ValueResultData [value=18125], ValueResultData [value=2.0], ValueResultData [value=123.0], ValueResultData [value=142.0], ValueResultData [value=4498.600000000002], ValueResultData [value=1.1699789539259888E-5], ValueResultData [value=9.498651393468875E-7], ValueResultData [value=6.08339376620762E-7]]], isController=ValueResultData [value=false]}]
2021-12-11 22:04:19,199 INFO o.a.j.r.d.JsonExporter: Creating statistics for other transactions
2021-12-11 22:04:19,199 DEBUG o.a.j.r.d.JsonExporter: Creating statistics for result data:MapResultData [map={data=ListResultData [items=[ValueResultData [value=[TG10TX3] <REDACTED>], ValueResultData [value=15000], ValueResultData [value=230], ValueResultData [value=1.5333333333333334], ValueResultData [value=1.8258000000000028], ValueResultData [value=0], ValueResultData [value=25], ValueResultData [value=2.0], ValueResultData [value=3.0], ValueResultData [value=3.0], ValueResultData [value=3.0], ValueResultData [value=9.150468903713162E-6], ValueResultData [value=1.7597972097375444E-8], ValueResultData [value=5.2793916292126333E-8]]], isController=ValueResultData [value=false]}]
2021-12-11 22:04:19,200 DEBUG o.a.j.r.d.JsonExporter: Creating statistics for result data:MapResultData [map={data=ListResultData [items=[ValueResultData [value=[TG10TX1] <REDACTED>], ValueResultData [value=514], ValueResultData [value=10], ValueResultData [value=1.9455252918287937], ValueResultData [value=171.44552529182874], ValueResultData [value=64], ValueResultData [value=3856], ValueResultData [value=98.0], ValueResultData [value=115.0], ValueResultData [value=127.0], ValueResultData [value=3220.4500000000044], ValueResultData [value=0.28588241444940937], ValueResultData [value=0.115374967601847], ValueResultData [value=0.015355012494841324]]], isController=ValueResultData [value=false]}]
2021-12-11 22:04:19,200 DEBUG o.a.j.r.d.JsonExporter: Creating statistics for result data:MapResultData [map={data=ListResultData [items=[ValueResultData [value=[TG10TX5] <REDACTED> Transaction], ValueResultData [value=500], ValueResultData [value=0], ValueResultData [value=0.0], ValueResultData [value=139.47400000000002], ValueResultData [value=75], ValueResultData [value=235], ValueResultData [value=142.0], ValueResultData [value=155.0], ValueResultData [value=160.95], ValueResultData [value=172.99], ValueResultData [value=0.2761083957384326], ValueResultData [value=0.11132615017784142], ValueResultData [value=0.05527560656872918]]], isController=ValueResultData [value=false]}]
2021-12-11 22:04:19,200 DEBUG o.a.j.r.d.JsonExporter: Creating statistics for result data:MapResultData [map={data=ListResultData [items=[ValueResultData [value=[TG10TX2] <REDACTED> Transaction], ValueResultData [value=665], ValueResultData [value=20], ValueResultData [value=3.007518796992481], ValueResultData [value=4774.747368421048], ValueResultData [value=65], ValueResultData [value=18125], ValueResultData [value=3917.0], ValueResultData [value=7708.199999999998], ValueResultData [value=10085.599999999995], ValueResultData [value=13883.720000000001], ValueResultData [value=0.36644448558908843], ValueResultData [value=0.15569962294102282], ValueResultData [value=0.049384120128216996]]], isController=ValueResultData [value=false]}]
2021-12-11 22:04:19,200 DEBUG o.a.j.r.d.JsonExporter: Creating statistics for result data:MapResultData [map={data=ListResultData [items=[ValueResultData [value=[TG10TX4] <REDACTED>], ValueResultData [value=2500], ValueResultData [value=46], ValueResultData [value=1.84], ValueResultData [value=120.9975999999999], ValueResultData [value=65], ValueResultData [value=540], ValueResultData [value=120.0], ValueResultData [value=132.0], ValueResultData [value=136.0], ValueResultData [value=147.0], ValueResultData [value=0.7160305785154739], ValueResultData [value=0.23962354889242957], ValueResultData [value=0.19858660576015094]]], isController=ValueResultData [value=false]}]
2021-12-11 22:04:19,200 INFO o.a.j.r.d.JsonExporter: Checking output folder
2021-12-11 22:04:19,200 INFO o.a.j.r.d.JsonExporter: Writing statistics JSON to <REDACTED>/statistics.json
2021-12-11 22:04:19,255 INFO o.a.j.r.d.ReportGenerator: Exporting data using exporter:'html' of className:'org.apache.jmeter.report.dashboard.HtmlTemplateExporter'
2021-12-11 22:04:19,257 DEBUG o.a.j.r.d.HtmlTemplateExporter: Start template processing
2021-12-11 22:04:19,258 INFO o.a.j.r.d.HtmlTemplateExporter: Will generate dashboard in folder: <REDACTED>
2021-12-11 22:04:19,434 INFO o.a.j.r.d.HtmlTemplateExporter: Report will be generated in: <REDACTED>, creating folder structure
2021-12-11 22:04:19,436 INFO o.a.j.r.d.TemplateVisitor: Copying folder from '/opt/apache-jmeter-5.4.1/bin/report-template' to '<REDACTED>', got message: <REDACTED>, found non empty folder with following content [<REDACTED>/statistics.json], will be ignored
2021-12-11 22:04:19,831 DEBUG o.a.j.r.d.HtmlTemplateExporter: End of template processing
2021-12-11 22:04:19,831 DEBUG o.a.j.r.d.ReportGenerator: End of data exporting
2021-12-11 22:04:19,831 DEBUG o.a.j.r.d.ReportGenerator: End of report generation
Any suggestions on what to dig into next?
It sounds like a bug in JMeter or in the WebSocket Sampler plugin, if you replace the plugin with some other sampler, like Debug Sampler or Dummy Sampler and the issue will be reproducible - raise an issue in JMeter Bugzilla
If the issue occurs only with WebSocket Samplers plugin open the issue in the plugin repository
In the meantime you can override the test start date by setting jmeter.reportgenerator.start_date just like you override the granularity and the test title.