search

PragmaticFlow / NBomber

Modern and flexible load testing framework for Pull and Push scenarios, designed to test any system regardless a protocol (HTTP/WebSockets/AMQP etc) or a semantic model (Pull/Push).
https://nbomber.com
Other
2.06k stars 130 forks source link

Unhandled exception: MetricsStatsActor failed #695

Open EduardGeorgiev opened 1 month ago

EduardGeorgiev commented 1 month ago

NBomber was stuck for 30 minutes on finalizing scenarios. I checked the logs:

2024-05-15 17:00:51.805 +01:00 [INF] [ThreadId:11] Plugins: no plugins were loaded
2024-05-15 17:00:51.806 +01:00 [INF] [ThreadId:11] Reporting sinks: no reporting sinks were loaded
2024-05-15 17:00:51.807 +01:00 [INF] [ThreadId:11] Starting init...
2024-05-15 17:00:51.822 +01:00 [INF] [ThreadId:11] Target scenarios: GPS Journey Ancillaries Load Test
2024-05-15 17:00:51.828 +01:00 [INF] [ThreadId:11] Init finished
2024-05-15 17:00:51.873 +01:00 [INF] [ThreadId:11] Starting bombing...
2024-05-15 17:12:54.054 +01:00 [INF] [ThreadId:37] Waiting on scenarios completion...
2024-05-15 17:26:32.867 +01:00 [FTL] [ThreadId:34] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:26:33.728 +01:00 [FTL] [ThreadId:28] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:26:41.062 +01:00 [FTL] [ThreadId:450] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:26:41.073 +01:00 [FTL] [ThreadId:450] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:26:41.076 +01:00 [FTL] [ThreadId:450] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:26:41.088 +01:00 [FTL] [ThreadId:450] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:26:41.099 +01:00 [FTL] [ThreadId:450] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:26:41.106 +01:00 [FTL] [ThreadId:450] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:34.718 +01:00 [FTL] [ThreadId:35] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:34.741 +01:00 [FTL] [ThreadId:35] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:34.765 +01:00 [FTL] [ThreadId:35] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:40.822 +01:00 [FTL] [ThreadId:33] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:40.836 +01:00 [FTL] [ThreadId:33] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:40.846 +01:00 [FTL] [ThreadId:33] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:40.873 +01:00 [FTL] [ThreadId:33] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:40.887 +01:00 [FTL] [ThreadId:33] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:40.912 +01:00 [FTL] [ThreadId:33] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()
2024-05-15 17:36:40.937 +01:00 [FTL] [ThreadId:33] Unhandled exception: MetricsStatsActor failed: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at HdrHistogram.Utilities.Bitwise.Log2(Int32 i)
   at HdrHistogram.Utilities.Bitwise.NumberOfLeadingZeros(Int64 value)
   at HdrHistogram.HistogramBase.RecordSingleValue(Int64 value)
   at NBomber.Domain.Stats.MetricsStatsActor.clo@128-6.MoveNext()

Sadly no reports were output and thus the test results were lost.

AntyaDev commented 1 month ago

Hi @EduardGeorgiev , Thank you for this information. Is it easy to reproduce? If yes what steps to be done to achieve the same effect?

EduardGeorgiev commented 1 month ago

Hello @AntyaDev . I am unsure of exactly what caused it, but here's some info: In the beginning I set:

        GCSettings.LatencyMode = GCLatencyMode.SustainedLowLatency;

Load Simulations:

        var trafficPerSecond = 150;
            Simulation.RampingInject(rate: (int)(trafficPerSecond * 1f), interval: TimeSpan.FromSeconds(1), during: TimeSpan.FromMinutes(1)), // 66% => 100%
            Simulation.Inject(rate: (int)(trafficPerSecond * 1f), interval: TimeSpan.FromSeconds(1), during: TimeSpan.FromMinutes(9)), // 100%
            Simulation.RampingInject(rate: (int)(trafficPerSecond * 2f), interval: TimeSpan.FromSeconds(1), during: TimeSpan.FromMinutes(1)), // 100% => 200%
            Simulation.Inject(rate: (int)(trafficPerSecond * 2f), interval: TimeSpan.FromSeconds(1), during: TimeSpan.FromMinutes(1)) // 200% for extra confidence

The scenario is .WithMaxFailCount(500000), I had more than 30K failures by the end of it.
My internet was slow, I believe it was still bombing even 30minutes after "Waiting on scenarios completion...", which was peculiar to me, as I was hoping NBomber to have some safeguards to alert me in case the requests are going out too slow for the requested bombing speed. My config:

{
  "TestSuite": "Ticket Options Tests",
  "TestName": "Ticket Options Load Test",
  "GlobalSettings": {
    "ReportFormats": [ "Html", "Txt", "Csv", "Md" ]
  }
}

Runner:

        var fileDate = DateTimeOffset.Now.ToUnixTimeSeconds().ToString();
        var runner = NBomberRunner
            .RegisterScenarios(scenarioTicketOptionsLoadTest)
            .LoadConfig("config.json")
            .WithReportFolder(Path.Combine(resultsDir, fileDate))
            .WithReportFileName($"report_{fileDate}")
            .WithLoggerConfig(() =>
                new LoggerConfiguration()
                    .MinimumLevel.Debug()
                    .WriteTo.File(
                        path: Path.Combine(solutionDir, "logs", "log.txt"),
                        outputTemplate:
                        "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] [ThreadId:{ThreadId}] {Message:lj}{NewLine}{Exception}",
                        rollingInterval: RollingInterval.Day)
            )
            .WithLicense(Settings.LicenseKey);

That's about it.

AntyaDev commented 1 month ago

Thanks, We will try to reproduce it. And I probably will ask more questions :)