5.4: low memory handlers with severity

[bwmeyer]

Since i have updated to the latest release of ravendb, I'm getting many "low memory handlers with severity" over time and the server seams to crash at the end.

I have seen, there is already a related issue published:
https://issues.hibernatingrhinos.com/issue/RavenDB-20968
But the issue is related to the 6.0 release.
Will this also be addressed in 5.4?

2023-08-21T07:33:24.2312201Z, 15, Operations, Server, Sparrow.LowMemory.LowMemoryNotification, Running 283 low memory handlers with severity: ExtremelyLow. Commit charge: 22.096 GBytes / 25.189 GBytes, Memory: 7.31 GBytes / 7.999 GBytes, Available memory for processing: 705.32 MBytes, Dirty memory: 0 Bytes, Managed memory: 205.93 MBytes, Unmanaged allocations: 31.21 MBytes, Lucene managed allocations for term cache: 2.79 MBytesLucene unmanaged allocations for sorting: 13.46 MBytes, Top unmanaged allocations: [#1] name: .NET ThreadPool Worker, allocations: 851.54 MBytes, managed thread id: 99, [#2] name: .NET ThreadPool Worker, allocations: 620.11 MBytes, managed thread id: 74, [#3] name: .NET ThreadPool Worker, allocations: 330.16 MBytes, managed thread id: 78, [#4] name: .NET ThreadPool Worker, allocations: 69.86 MBytes, managed thread id: 29, [#5] name: .NET ThreadPool Worker, allocations: 41.64 MBytes, managed thread id: 7
2023-08-21T07:33:27.2857936Z, 15, Operations, Server, Sparrow.LowMemory.LowMemoryNotification, Running 283 low memory handlers with severity: ExtremelyLow. Commit charge: 22.143 GBytes / 25.189 GBytes, Memory: 7.356 GBytes / 7.999 GBytes, Available memory for processing: 658.18 MBytes, Dirty memory: 0 Bytes, Managed memory: 271.96 MBytes, Unmanaged allocations: 37.52 MBytes, Lucene managed allocations for term cache: 2.79 MBytesLucene unmanaged allocations for sorting: 13.46 MBytes, Top unmanaged allocations: [#1] name: .NET ThreadPool Worker, allocations: 864.97 MBytes, managed thread id: 99, [#2] name: .NET ThreadPool Worker, allocations: 635.43 MBytes, managed thread id: 74, [#3] name: .NET ThreadPool Worker, allocations: 329.34 MBytes, managed thread id: 78, [#4] name: .NET ThreadPool Worker, allocations: 83.65 MBytes, managed thread id: 29, [#5] name: .NET ThreadPool Worker, allocations: 45.61 MBytes, managed thread id: 7
2023-08-21T07:33:30.3151880Z, 15, Operations, Server, Sparrow.LowMemory.LowMemoryNotification, Running 283 low memory handlers with severity: ExtremelyLow. Commit charge: 22.166 GBytes / 25.189 GBytes, Memory: 7.383 GBytes / 7.999 GBytes, Available memory for processing: 631.09 MBytes, Dirty memory: 0 Bytes, Managed memory: 247.51 MBytes, Unmanaged allocations: 25.2 MBytes, Lucene managed allocations for term cache: 2.79 MBytesLucene unmanaged allocations for sorting: 0 Bytes, Top unmanaged allocations: [#1] name: .NET ThreadPool Worker, allocations: 879.38 MBytes, managed thread id: 99, [#2] name: .NET ThreadPool Worker, allocations: 635.5 MBytes, managed thread id: 74, [#3] name: .NET ThreadPool Worker, allocations: 328.45 MBytes, managed thread id: 78, [#4] name: .NET ThreadPool Worker, allocations: 97.1 MBytes, managed thread id: 29, [#5] name: .NET ThreadPool Worker, allocations: 45.73 MBytes, managed thread id: 7
2023-08-21T07:33:33.3495392Z, 15, Operations, Server, Sparrow.LowMemory.LowMemoryNotification, Running 283 low memory handlers with severity: ExtremelyLow. Commit charge: 22.236 GBytes / 25.189 GBytes, Memory: 7.435 GBytes / 7.999 GBytes, Available memory for processing: 577.82 MBytes, Dirty memory: 0 Bytes, Managed memory: 278.32 MBytes, Unmanaged allocations: 47.62 MBytes, Lucene managed allocations for term cache: 2.79 MBytesLucene unmanaged allocations for sorting: 13.46 MBytes, Top unmanaged allocations: [#1] name: .NET ThreadPool Worker, allocations: 893.96 MBytes, managed thread id: 99, [#2] name: .NET ThreadPool Worker, allocations: 648.96 MBytes, managed thread id: 74, [#3] name: .NET ThreadPool Worker, allocations: 328.45 MBytes, managed thread id: 78, [#4] name: .NET ThreadPool Worker, allocations: 125.06 MBytes, managed thread id: 29, [#5] name: .NET ThreadPool Worker, allocations: 61.51 MBytes, managed thread id: 7
2023-08-21T07:33:37.7222163Z, 74, Operations, Server/TCP, Raven.Server.RavenServer, Failed to accept new tcp connection again, will wait 1 seconds before retrying, EXCEPTION: System.InvalidOperationException: Not listening. You must call the Start() method before calling this method.
   at System.Net.Sockets.TcpListener.AcceptSocketAsync(CancellationToken cancellationToken)
   at System.Net.Sockets.TcpListener.AcceptTcpClientAsync()
   at Raven.Server.RavenServer.AcceptTcpClientAsync(TcpListener listener) in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\RavenServer.cs:line 2214

[grisha-kotler]

What build version are you using?
Do you have the stack traces of the threads that are mentioned in the notification?
Can you enable the information logs?

[bwmeyer]

RavenDB: 5.4.109.54071
.NET runtime: 7.0.9
Operating System: Windows 10 Pro 22H2, 10.0.19045 Build 1904, 8GB RAM (4.5GB free)
I cannot see a stack trace mentioned by the LowMemoryNotification.
All logged exceptions I can see (var logs and Windows event viewer) are only from database clients and not related in a timely fashion.

I could change the log mode but this will take some time, as I need to publish a new release and need then to wait for the issue to reoccurre. I need a find a slot, when I can to make this change in the productive environment.

The issue was also observed on a Windows 2022 Standard Server.

[bwmeyer]

I was now able to get an informational log when the issue occurred.
There is only some exception about loading additional assembly.
As the log contains confidential data, please let me know where I can send it to (if interested).

2023-08-21T18:03:58.9241214Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\librvnpal.win.x64.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98
2023-08-21T18:03:58.9340915Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Attempting to load additional assembly from 'C:\Apps\RavenDBServer\librvnpal.win.x86.dll'.
2023-08-21T18:03:58.9342555Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\librvnpal.win.x86.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98
2023-08-21T18:03:58.9343137Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Attempting to load additional assembly from 'C:\Apps\RavenDBServer\librvnpal.win7.x64.dll'.
2023-08-21T18:03:58.9344358Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\librvnpal.win7.x64.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98
2023-08-21T18:03:58.9344827Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Attempting to load additional assembly from 'C:\Apps\RavenDBServer\librvnpal.win7.x86.dll'.
2023-08-21T18:03:58.9346006Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\librvnpal.win7.x86.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98
2023-08-21T18:03:58.9346452Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Attempting to load additional assembly from 'C:\Apps\RavenDBServer\libsodium.win.x64.dll'.
2023-08-21T18:03:58.9347545Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\libsodium.win.x64.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98
2023-08-21T18:03:58.9348043Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Attempting to load additional assembly from 'C:\Apps\RavenDBServer\libsodium.win.x86.dll'.
2023-08-21T18:03:58.9349288Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\libsodium.win.x86.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98
2023-08-21T18:03:58.9349776Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Attempting to load additional assembly from 'C:\Apps\RavenDBServer\libzstd.win.x64.dll'.
2023-08-21T18:03:58.9351015Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\libzstd.win.x64.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98
2023-08-21T18:03:58.9351458Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Attempting to load additional assembly from 'C:\Apps\RavenDBServer\libzstd.win.x86.dll'.
2023-08-21T18:03:58.9352718Z, 13, Information, Server, Raven.Server.Documents.Indexes.Static.IndexCompiler, Could not load additional assembly from 'C:\Apps\RavenDBServer\libzstd.win.x86.dll'., EXCEPTION: System.BadImageFormatException: PE image does not have metadata.
   at System.Reflection.Metadata.MetadataReader.GetAssemblyName(String assemblyFile)
   at Raven.Server.Documents.Indexes.Static.IndexCompiler.DiscoverAdditionalAssemblies() in C:\Builds\RavenDB-Stable-5.4\54071\src\Raven.Server\Documents\Indexes\Static\IndexCompiler.cs:line 98

[grisha-kotler]

Please send it to [email protected].