The amount of available memory to commit on the system is low - Raspberry Pi 3

[Adam Novák]

Hi,
I've ran into this quite weird issue where it reports that my PI3 has not enough memory. The database is completely empty. Any ideas why?

Unhandled Exception: System.InsufficientExecutionStackException: The amount of available memory to commit on the system is low. Commit charge: 606.89 MBytes / 563.66 MBytes. Memory: 926.7 MBytes / 927.32 MBytes Will not create a new thread in this situation because it may result in a stack overflow error when trying to allocate stack space but there isn't sufficient memory for that.
   at Sparrow.LowMemory.MemoryInformation.ThrowInsufficentMemory(MemoryInfoResult memInfo) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\LowMemory\MemoryInformation.cs:line 119

[Oren Eini (Ayende Rahien)]

Can you send the output of:

   cat /proc/meminfo ?

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Adam Novák]

I forgot to add that this happened on the stable version of 4.0.0. First I thought it was my fault and it was caused by corrupted database (because I used old RC dependency), but I cleaned up the database multiple times and I pretty much always get this error. The database is almost empty so I see not reason why it should need more memory.

MemTotal:         949580 kB
MemFree:          463832 kB
MemAvailable:     654248 kB
Buffers:           14276 kB
Cached:           272660 kB
SwapCached:            0 kB
Active:           261524 kB
Inactive:         188488 kB
Active(anon):     163192 kB
Inactive(anon):    56884 kB
Active(file):      98332 kB
Inactive(file):   131604 kB
Unevictable:           8 kB
Mlocked:               8 kB
SwapTotal:        102396 kB
SwapFree:         102396 kB
Dirty:                64 kB
Writeback:             0 kB
AnonPages:        163080 kB
Mapped:            97604 kB
Shmem:             57004 kB
Slab:              21236 kB
SReclaimable:      11068 kB
SUnreclaim:        10168 kB
KernelStack:        1632 kB
PageTables:         2004 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      577184 kB
Committed_AS:     688516 kB
VmallocTotal:    1114112 kB
VmallocUsed:           0 kB
VmallocChunk:          0 kB
CmaTotal:           8192 kB
CmaFree:            6792 kB

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

CommitLimit:      577184 kB

This is really strange, and the reason for this issue. 

As a workaround, try setting env variable: RAVEN_IN_DOCKER=true

Then run ravendb?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

Not sure what exactly that does, but it seems it didn't help. I also realised I didn't mention I run ravendb on latest raspbian lite. I managed to get it working yesterday for a bit and it seemed really slow, I was unable to get it working again though, not sure if that helps. I tried redownloading RavenDB in case something got corrupted, but same result. A bit more from the stacktrace

• Sparrow.LowMemory.MemoryInformation.ThrowInsufficentMemory(MemoryInfoResult memInfo) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\LowMemory\MemoryInformation.cs

• Sparrow.LowMemory.MemoryInformation.AssertNotAboutToRunOutOfMemory(float minimumFreeCommittedMemory) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\LowMemory\MemoryInformation.cs

• Sparrow.Utils.NativeMemory.AllocateMemory(long size, out ThreadStats thread) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\Utils\NativeMemory.cs

• Sparrow.Json.ArenaMemoryAllocator..ctor(SharedMultipleUseFlag lowMemoryFlag, int initialSize) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\Json\ArenaMemoryAllocator.cs

• Sparrow.Json.JsonOperationContext..ctor(int initialSize, int longLivedSize, SharedMultipleUseFlag lowMemoryFlag) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\Json\JsonOperationContext.cs

• Sparrow.Json.JsonContextPool.CreateContext() in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\Json\JsonContextPool.cs

• Sparrow.Json.JsonContextPoolBase.AllocateOperationContext(out T context) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\Json\JsonContextPoolBase.cs

• Sparrow.Json.JsonContextPoolBase.AllocateOperationContext(out JsonOperationContext context) in C:\Builds\RavenDB-Stable-4.0\src\Sparrow\Json\JsonContextPoolBase.cs

• Raven.Client.Documents.Session.InMemoryDocumentSessionOperations..ctor(string databaseName, DocumentStoreBase documentStore, RequestExecutor requestExecutor, Guid id) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Session\InMemoryDocumentSessionOperations.cs

• Raven.Client.Documents.Session.DocumentSession..ctor(string dbName, DocumentStore documentStore, Guid id, RequestExecutor requestExecutor) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Session\DocumentSession.cs

• Raven.Client.Documents.DocumentStore.OpenSession(SessionOptions options) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\DocumentStore.cs

• Raven.Client.Documents.DocumentStore.OpenSession() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\DocumentStore.cs

[Grisha Kotler]

It looks like the env variable wasn't applied.

Hibernating Rhinos Ltd  

Grisha Kotler l RavenDB Core Team Developer l Mobile: +972-54-586-8647

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/

--

[Adam Novák]

It was in `printenv` output "RAVEN_IN_DOCKER=true"




To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Adi Avivi]

RavenDB makes use of CommittedLimit value.  It should be changed to Phys Mem size (plus swap size)

. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .

Hibernating Rhinos Ltd                      

Avivi Adi l Core Team

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811
RavenDB paving the way to "Data Made Simple"   http://ravendb.net

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

How can I do that?

I was thinking its way too weird that it would need so much memory and it must happen sometime during initialization since from console it reports 0 documents. Also this code (didn't make many changes to it since, the only related to databse being update of the nuget dependency) didn't have this issue on RC version or some nightlies (2 weeks ago?) I tried cause there was a different issue with the RC. I can try and verify (tomorrow) that nothing has changed on that part and that it actually still works on the RC version and there is no issue with the build process or some change in the OS that could've caused this.

[Adam Novák]

So I rebuilt my project with NuGet 4.0.0-rc-40025, installed the same version on the server and started both... and it worked. It timeouted on indexing quite a bit longer than I expected (maybe bug, maybe slow Pi I/O) but after a restart and few minutes of loading :O it was snappy. so I'd say its fair to say that this is issue introduced between last RC and release and is not cause by my code.

Just to be sure I didn't fix it right now I repeated the exact steps with stable version I double checked I didn't forget anything and... InsufficientExecutionStackException: The amount of available memory to commit on the system is low. Commit charge: 772.26 MBytes / 563.66 MBytes.

[Oren Eini (Ayende Rahien)]

That is a known issue in the way we compute memory.

The issue is a config value on Linux called: vm.overcommit_ratio

Please make sure that it is set to at least 100.

See here for details: 

https://www.kernel.org/doc/Documentation/vm/overcommit-accounting

The problem is that you probably have vm.overcommit_memory set to a value other than 2, so it is ignored by Linux, but we are looking at it.

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

On Tue, Feb 13, 2018 at 8:46 PM, Adam Novák <adsa...@gmail.com> wrote:

So I rebuilt my project with NuGet 4.0.0-rc-40025, installed the same version on the server and started both... and it worked. It timeouted on indexing quite a bit longer than I expected (maybe bug, maybe slow Pi I/O) but after a restart and few minutes of loading :O it was snappy. so I'd say its fair to say that this is issue introduced between last RC and release and is not cause by my code.

Just to be sure I didn't fix it right now I repeated the exact steps with stable version I double checked I didn't forget anything and... InsufficientExecutionStackException: The amount of available memory to commit on the system is low. Commit charge: 772.26 MBytes / 563.66 MBytes.

[Adam Novák]

I don't think it is caused by this. I think there is more likely some leak. But I followed your suggestion and as I thought it managed to save a bit into database but failed soon after with  The amount of available memory to commit on the system is low. Commit charge: 991.25 MBytes / 1.003 GBytes. Memory: 926.68 MBytes / 927.32 MBytes Will not create a new thread in this situation because it may result in a stack overflow error when trying to allocate stack space but there isn't sufficient memory for that.

Previously I had value of 50 so now it just doubled the limit which it reached anyway and the database still had only a few documents.

I think the problem is the fact that it actually needs so much memory. I can never think of normal scenario where request to save at most 1MB of data (or maybe it is caused sooner?) would result in requirement of 600 or more MB. The database is pretty much empty, why would it need so much memory for a commit.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

Can you provide a way to reproduce this?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

I created a small program that causes this issue on my side. It isn't exactly Unit test, because I didn't know how to run unit test on rpi. The exception is thrown with document save changes.

https://codeshare.io/2j6w0B

[Adam Novák]

Oh sorry I forgot to mention that I have this problem only on rpi, if I run it on PC everything is fine. Also I suspect the issue is somewhere in the C# driver, because when I tested it I once ran last RC version of the server with Stable driver and the exception was there. It completely slipped my mind.

[Oren Eini (Ayende Rahien)]

What is actually crashing here? The server or the client? 

[Adam Novák]

The server I'd say, client crashes too, but that is because this exception isn't handled. What I meant with the client is that it might be generating huge commits as a result of some bug, which might duplicate the requests it has or something like that. I have not looked inside the client so I might be completely wrong and there is no way that is happening I just thought I'd mention it. Sorry if I caused confusion with it.

[Oren Eini (Ayende Rahien)]

What happens if you are trying to run the client from _another_ machine?

[Adam Novák]

It seems fine. No crashes.

[Oren Eini (Ayende Rahien)]

So the server on the Pi works in this case? 

[Adam Novák]

yes

[Oren Eini (Ayende Rahien)]

Okay, can you test this with our latest nightly build?

[Adam Novák]

I tested it on the project I shared, it worked fine. The only way I managed that was with multiple threads and quite a few of them (somewhere between 24/32) which could be fair, but it still seems quite low considering I am saving just a very small amount of data? I have no clue what the average memory usage of a commit is so again I could be wrong, just making sure.

I also tested it on my own project and I ran into this issue "Unable to find an entry point named 'crypto_generichash_statebytes' in DLL 'libsodium.arm.so' ". I have up-to-date raspbian lite. I can't test it more on the project until I get this sorted but I can already say it works better, because it actually ran for a bit instead of dying during initialization.


This is exception with 40 threads
Unhandled Exception: System.InsufficientExecutionStackException: The amount of available memory to commit on the system is low. Commit charge: 1,013.19 MBytes / 1.003 GBytes. Memory: 320.7 MBytes / 927.32 MBytes Will not create a new thread in this situation because it may result in a stack overflow error when trying to allocate stack space but there isn't sufficient memory for that.

On Monday, February 19, 2018 at 2:30:46 PM UTC+1, Oren Eini wrote:

Okay, can you test this with our latest nightly build?

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

On Sun, Feb 18, 2018 at 9:24 PM, Adam Novák <adsa...@gmail.com> wrote:

yes

On Sunday, February 18, 2018 at 8:23:59 PM UTC+1, Oren Eini wrote:

So the server on the Pi works in this case? 

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Adam Novák]

I recompiled the whole libsodium library (libsodium.org) to make sure it was up to date and the exception is still there. I looked at the source and found that I have no idea how exactly does this mapping work because I've never done it. I have looked at both raven and libsodium sources and I could not find a single reason why it wouldn't work for this method. The exception is as follows

Raven.Client.Exceptions.RavenException: System.EntryPointNotFoundException: Unable to find an entry point named 'crypto_generichash_statebytes' in DLL 'libsodium.arm.so'.
   at Sparrow.Sodium.Posix.Arm.crypto_generichash_statebytes()
   at Sparrow.Sodium.Posix.crypto_generichash_statebytes() in C:\Builds\RavenDB-4.0-Nightly\src\Sparrow\Sodium.cs:line 1978
   at Sparrow.Sodium.crypto_generichash_statebytes() in C:\Builds\RavenDB-4.0-Nightly\src\Sparrow\Sodium.cs:line 602
   at Raven.Server.Documents.ComputeHttpEtags.ComputeEtagForDocuments(List`1 documents, List`1 includes) in C:\Builds\RavenDB-4.0-Nightly\src\Raven.Server\Documents\ComputeHttpEtags.cs:line 46
   at Raven.Server.Documents.Handlers.DocumentHandler.<GetDocumentsByIdAsync>d__4.MoveNext() in C:\Builds\RavenDB-4.0-Nightly\src\Raven.Server\Documents\Handlers\DocumentHandler.cs:line 177
...

[Oren Eini (Ayende Rahien)]

I'm not sure that I'm following. This is the error you are getting on the _nightly_ now?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

Yes, I'll have to work on being more clear sorry. I just noticed a weird thing... why is there C:\ when this error is taken straight from raspi on linux, not windows?

[Oren Eini (Ayende Rahien)]

You should be able to just place the libsodium.arm.so file right next to the Raven.Server.dll file and that should pick it up.

That said, this already should be there.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Oren Eini (Ayende Rahien)]

That is the build server paths for the stack traces

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

It is there

[Oren Eini (Ayende Rahien)]

Can you try using strace, to see where it is trying to look it up? 

[Adam Novák]

I wasn't able to find the open with strace command so I selected an easier path for me, just removing the dll. When I removed it the error changed from Unable to find an entry point named 'crypto_generichash_statebytes' in DLL 'libsodium.arm.so'. to Dll does not exist so I'd say it loads the dll that comes with RavenDB.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

Hm... that is really strange.

If you place the lib you compiled in the same place, what happens?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

It seems the issue doesn't show up anymore, but

 Error occurred during execution of 'Worker #6e0105e2' process. Execution will be retried (attempt #3) in 00:00:08 seconds.
System.InsufficientExecutionStackException: The amount of available memory to commit on the system is low. Commit charge: 994.48 MBytes / 1.003 GBytes. Memory: 351.07 MBytes / 927.32 MBytes Will not create a new thread in this situation because it may result in a stack overflow error when trying to allocate stack space but there isn't sufficient memory for that.

is back again. I looked at the stats and the database was really empty, it had 1-4 docs. This all worked without memory issues on the RC. Below is the lib I used, it's much beefier couldn't the method just got stripped?

https://drive.google.com/file/d/1cvNDo_jcm8NZEgk0y0cf7uUPPwCjjmoh/view?usp=sharing

[Oren Eini (Ayende Rahien)]

It is possible that we are using the wrong one, yes.

We'll check that.

Can you set RAVEN_IN_DOCKER environment variable and try again? That should disable this check

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

So just to check.. environment variables are printed with `printenv` and it there shoudl be `RAVEN_IN_DOCKER=true` right? Thats what I have and it still throws the exception so I dunno what am I doing wrong wrong.

[Oren Eini (Ayende Rahien)]

Yes.

Can you also check the 4.0.1

We will be looking into this internally this week, BTW, so you can just wait a bit and we'll resolve it

[Adam Novák]

So I tested it on 4.0.2. I haven't ran into the memory issue yet but I wasn't able to test it properly because I kept running into auto index creation timeout error and didn't have the time (hopefully this week) to implement manual index creation. Also the libsodium issue is still there... Fixed it again with my own build of the library. There were some more exceptions that seem to be caused by Raven but I am thinking of creating new thread once I get to test everything properly since the original issue seems to be solved.

[Oren Eini (Ayende Rahien)]

What do you mean, auto index creation timeout issue?

That should only ever happen if you are running in a cluster and can't reach the other members.

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

On Mon, Mar 5, 2018 at 10:34 AM, Adam Novák <adsa...@gmail.com> wrote:

So I tested it on 4.0.2. I haven't ran into the memory issue yet but I wasn't able to test it properly because I kept running into auto index creation timeout error and didn't have the time (hopefully this week) to implement manual index creation. Also the libsodium issue is still there... Fixed it again with my own build of the library. There were some more exceptions that seem to be caused by Raven but I am thinking of creating new thread once I get to test everything properly since the original issue seems to be solved.

--

[Adam Novák]

I meant exception not issue, sorry. The exception says that auto-index creation timed out after 15s, I suspected it has something to do with slower raspberry I/O. These are the two exceptions index related I got

NotSupportedException: System.NotSupportedException: Index Auto/RavenJobs/ByStateData.Name is in-memory implementation of a faulty index ---> Raven.Server.Exceptions.IndexOpenException: Could not open index from '/home/signals/RavenDB/Server/RavenData/Databases/hangfire/Indexes/Auto_RavenJobs_ByStateData.Name'. ---> System.NullReferenceException: Object reference not set to an instance of an object.
at Voron.Data.BTrees.Tree.SearchForPage(Slice key, TreeNodeHeader*& node) in C:\Builds\RavenDB-Stable-4.0\src\Voron\Data\BTrees\Tree.cs:line 636
at Voron.Data.BTrees.Tree.DirectRead(Slice key) in C:\Builds\RavenDB-Stable-4.0\src\Voron\Data\BTrees\Tree.cs:line 1145
at Voron.Impl.Transaction.ReadTree(Slice treeName, RootObjectType type, Boolean isIndexTree, NewPageAllocator newPageAllocator) in C:\Builds\RavenDB-Stable-4.0\src\Voron\Impl\Transaction.cs:line 76
at Voron.StorageEnvironment.LoadExistingDatabase() in C:\Builds\RavenDB-Stable-4.0\src\Voron\StorageEnvironment.cs:line 287
at Voron.StorageEnvironment..ctor(StorageEnvironmentOptions options) in C:\Builds\RavenDB-Stable-4.0\src\Voron\StorageEnvironment.cs:line 145

IndexCreationException: Raven.Client.Exceptions.Documents.Indexes.IndexCreationException: Failed to create auto index: Auto/RavenJobs/ByStateData.Name, the cluster is probably down. Node A state is Leader, I'm the only one in the cluster, so I'm the leader (at 06/03/2018 08:49:05) ---> System.TimeoutException: Waited for 00:00:15 but the command was not applied in this time.
at Raven.Server.Rachis.Leader.<PutAsync>d__44.MoveNext() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Rachis\Leader.cs:line 633
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at Raven.Server.ServerWide.ServerStore.<SendToLeaderAsyncInternal>d__114.MoveNext() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\ServerWide\ServerStore.cs:line 1490

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

These errors are really strange, are they reproducible for you?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

Yes, although 4.0.3 improved it a little because I had to add more indexes for it to actually show. https://codeshare.io/5XlLQM
on 4.0.2 1 query was enough.

I have suspicion that it is caused with writes because when I rerun it it doesn't throw the exception (it behaves similiarly in my project).

Unhandled Exception: Raven.Client.Exceptions.Documents.Indexes.IndexCreationException: Raven.Client.Exceptions.Documents.Indexes.IndexCreationException: Failed to create auto index: Auto/TestDocuments/ByBooleanAndName.LengthAndTitle.LengthAndValue, the cluster is probably down. Node A state is Leader, I'm the only one in the cluster, so I'm the leader (at 08/03/2018 13:51:01) ---> System.TimeoutException: Waited for 00:00:15 but didn't get index notification for 4. Last commit index is: 3. Number of errors is: 0.

   at Raven.Server.ServerWide.RachisLogIndexNotifications.ThrowTimeoutException(TimeSpan value, Int64 index, Int64 lastModifiedIndex) in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\ServerWide\ClusterStateMachine.cs:line 1447
   at Raven.Server.ServerWide.RachisLogIndexNotifications.<WaitForIndexNotification>d__7.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\ServerWide\ClusterStateMachine.cs:line 1431

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Server.Documents.Indexes.IndexStore.<CreateIndex>d__24.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Documents\Indexes\IndexStore.cs:line 399
   --- End of inner exception stack trace ---
   at Raven.Server.Documents.Indexes.IndexStore.<CreateIndex>d__24.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Documents\Indexes\IndexStore.cs:line 407

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Server.Documents.Queries.Dynamic.DynamicQueryRunner.<MatchIndex>d__7.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Documents\Queries\Dynamic\DynamicQueryRunner.cs:line 102

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Server.Documents.Queries.Dynamic.DynamicQueryRunner.<ExecuteQuery>d__3.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Documents\Queries\Dynamic\DynamicQueryRunner.cs:line 39

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Server.Documents.Queries.QueryRunner.<ExecuteQuery>d__5.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Documents\Queries\QueryRunner.cs:line 54

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Server.Documents.Handlers.QueriesHandler.<Query>d__4.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Documents\Handlers\QueriesHandler.cs:line 105

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Server.Documents.Handlers.QueriesHandler.<HandleQuery>d__2.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Documents\Handlers\QueriesHandler.cs:line 53

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Server.Routing.RequestRouter.<HandlePath>d__6.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\Routing\RequestRouter.cs:line 97

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ValueTaskAwaiter`1.GetResult()
   at Raven.Server.RavenServerStartup.<RequestHandler>d__11.MoveNext() in C:\Builds\RavenDB-4.0-Patch\src\Raven.Server\RavenServerStartup.cs:line 159
   at Raven.Client.Exceptions.ExceptionDispatcher.<Throw>d__3.MoveNext() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Exceptions\ExceptionDispatcher.cs:line 117

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Http.RequestExecutor.<HandleUnsuccessfulResponse>d__87`1.MoveNext() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Http\RequestExecutor.cs:line 967

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at Raven.Client.Http.RequestExecutor.<ExecuteAsync>d__72`1.MoveNext() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Http\RequestExecutor.cs:line 723

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at Raven.Client.Http.RequestExecutor.<ExecuteAsync>d__72`1.MoveNext() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Http\RequestExecutor.cs:line 763

--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Util.AsyncHelpers.RunSync(Func`1 task) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Util\AsyncHelpers.cs:line 37
   at Raven.Client.Http.RequestExecutor.Execute[TResult](RavenCommand`1 command, JsonOperationContext context, SessionInfo sessionInfo) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Http\RequestExecutor.cs:line 316
   at Raven.Client.Documents.Session.DocumentQuery`1.ExecuteActualQuery() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Session\DocumentQuery.cs:line 821
   at Raven.Client.Documents.Session.DocumentQuery`1.InitSync() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Session\DocumentQuery.cs:line 813
   at Raven.Client.Documents.Session.DocumentQuery`1.GetQueryResult() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Session\DocumentQuery.cs:line 312
   at Raven.Client.Documents.Linq.RavenQueryProviderProcessor`1.ExecuteQuery[TProjection]() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Linq\RavenQueryProviderProcessor.cs:line 2694
   at Raven.Client.Documents.Linq.RavenQueryProviderProcessor`1.Execute(Expression expression) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Linq\RavenQueryProviderProcessor.cs:line 2664
   at Raven.Client.Documents.Linq.RavenQueryProvider`1.Execute(Expression expression) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Linq\RavenQueryProvider.cs:line 125
   at Raven.Client.Documents.Linq.RavenQueryProvider`1.System.Linq.IQueryProvider.Execute(Expression expression) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Linq\RavenQueryProvider.cs:line 197
   at Raven.Client.Documents.Linq.RavenQueryInspector`1.GetEnumerator() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Linq\RavenQueryInspector.cs:line 83
   at System.Collections.Generic.List`1.AddEnumerable(IEnumerable`1 enumerable)
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at RavenDebug.Program.Main(String[] args) in D:\Stuff\RavenDebug\RavenDebug\Program.cs:line 125

[Oren Eini (Ayende Rahien)]

Question, are you running this on the PI with a flash card? 

If you are loaded with writes, we saw some ridiculous latencies for some cards. 

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

well Raven is running on the main microSD, seemed like the most performant option for the pi.

[Oren Eini (Ayende Rahien)]

Can you check the i/o latencies when this happens?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

There is a bit of an wait, but I wouldn't call it ridiculous. There were longer wait times during the actual write. 8s longest I could find and I think reallocation might've happened there. Usually it is around 2s or less.

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00     4.50    0.00    4.50     0.00    28.00    12.44     6.01 1024.44    0.00 1024.44 222.22 100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00     1.00    0.00    3.00     0.00    62.00    41.33    26.25 1946.67    0.00 1946.67 333.33 100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00     0.00    0.00    5.50     0.00    96.00    34.91    22.93 3141.82    0.00 3141.82 181.82 100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00     0.00    0.00    5.00     0.00  2232.00   892.80    19.98 4976.00    0.00 4976.00 200.00 100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00     0.00    0.00    4.00     0.00   844.00   422.00    23.58 4531.25    0.00 4531.25 250.00 100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00     0.00    0.00   10.00     0.00   106.00    21.20    11.71 3949.50    0.00 3949.50 100.00 100.00

EXCEPTION

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00     5.00    0.00    5.00     0.00  1356.00   542.40     4.26  963.00    0.00  963.00 200.00 100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
mmcblk0           0.00    21.00    0.00   11.50     0.00   180.00    31.30     2.21  255.65    0.00  255.65  86.09  99.00

[Oren Eini (Ayende Rahien)]

I think that this is possible because you are looking at an individual write speeds.

If you run strace, can you see how much the write system call take? In particular to the system/raven.voron file?

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

[Adam Novák]

The demo is writting several thousand entries before it actually starts querying. How can I measure it in sensible manner? 
strace RavenDB/run.sh 2> strace.log & sleep 30 && dotnet test/RavenDebug.dll
this just dies after Hello world...

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

This should do it:

strace -p RAVEB_PID -f  

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Oren Eini (Ayende Rahien)]

The -f is so it will gather the information from all the threads

[Adam Novák]

When I ran it with the main process pid (...../run.sh) all I got is

strace: Process 9229 attached
wait4(-1, strace: Process 9229 detached
 <detached ...>

[Oren Eini (Ayende Rahien)]

I suggest we setup a screen sharing call to help with this

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

I dont think that will be needed. I managed to get it running once I just started ravendb with strace.. the log is just massive though... 650MB and it slowed the whole thing quite a bit. Total of 11 calls to that file. I didn't get index timeout though, but it timed out on one request which is to be expected since this is quite a lot of extra write to the card.

Couldn't it be solved by just increasing the timeout to double the value?

[pid 5943] open(".../System/Raven.voron", O_RDWR|O_CREAT|O_LARGEFILE, 0600) = 149

[pid 5943] lstat64(".../System/Raven.voron", {st_mode=S_IFREG|0600, st_size=0, ...}) = 0

[pid 5961] lstat64(".../System/Raven.voron", {st_mode=S_IFREG|0600, st_size=65536, ...}) = 0

[pid 5961] lstat64(".../System/Raven.voron", <unfinished ...>

...

[pid 5961] lstat64(".../System/Raven.voron", {st_mode=S_IFREG|0600, st_size=262144, ...}) = 0

[pid 5961] lstat64(".../System/Raven.voron", {st_mode=S_IFREG|0600, st_size=8388608, ...}) = 0

[Oren Eini (Ayende Rahien)]

It's possible, but I'm would like to see what it is doing.

Note you can limit things to a specific path as well, to reduce the log size.

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

--

[Adam Novák]

I came up with
strace -Tf -P ".../System/Raven.voron" RavenDB/run.sh 2> strace.log

I don't really know what am I looking for, the log is much smaller now and I hope it should have times. I got the error captured but I didnt manage to get when the error happened written to the log

Most of the log are mmap2 calls and they are usually withing millisecond or less. 3 of them are 1s and than there is this piece. Which could be the spot where it happened (position in file looks very roughly the same as the part where it crashed), but I am not gonna pretend I understand the log.

[pid 7702] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0x640000) = 0x55561000 <0.000074>

[pid 7702] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0 <unfinished ...>

[pid 7435] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0 <unfinished ...>

[pid 7702] <... mmap2 resumed> ) = 0x55531000 <3.458179>

[pid 7702] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0x860000) = 0x55511000 <0.000092>

[pid 7702] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0x8b0000 <unfinished ...>

[pid 7716] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0x640000 <unfinished ...>

[pid 7702] <... mmap2 resumed> ) = 0x55501000 <0.001465>

[pid 7716] <... mmap2 resumed> ) = 0x554f1000 <0.000125>

[pid 7435] <... mmap2 resumed> ) = 0x55521000 <3.416938>

[pid 7716] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0x870000) = 0x554c1000 <0.000070>

[pid 7435] mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 149, 0x660000) = 0x55471000 <0.001085>

[Oren Eini (Ayende Rahien)]

I would really suggest doing a skype call with Adi, one of our Linux exports that can dig deep into this.

The typical 24 hours roundtrip between question / answer is really painful to resolving things.

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

[Adam Novák]

Ok, how do I find him?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Adi Avivi]

Hi Adam.  Lets set a skype meeting. How about tomorrow at 1:00pm GMT (my 3pm) ?

. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .

Hibernating Rhinos Ltd                      
Avivi Adi l Core Team

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple"   http://ravendb.net

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Adam Novák]

I won't have much time around 1pm GMT, but my thursday is basically free.

[Adi Avivi]

Thursday even better.  1pm GMT will be good?

. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .

Hibernating Rhinos Ltd                      
Avivi Adi l Core Team
Office: +972-4-622-7811 l Fax: +972-153-4-622-7811
RavenDB paving the way to "Data Made Simple"   http://ravendb.net

On Tue, Mar 13, 2018 at 2:25 PM, Adam Novák <adsa...@gmail.com> wrote:

I won't have much time around 1pm GMT, but my thursday is basically free.

--

[Adam Novák]

yes

[Adi Avivi]

Conclusion of the skype call:

Because of extremely slow disk I/O rate (SDCard), we've set Cluster.OperationTimeoutInSec=180,
and the exception: "Raven.Client.Exceptions.Documents.Indexes.IndexCreationException: Raven.Client.Exceptions.Documents.Indexes.IndexCreationException: Failed to create auto index: Auto/RavenJobs/ByCountReducedByStateData.Name, the cluster is probably down. Node A state is Leader, I'm the only one in the cluster, so I'm the leader (at 13/03/2018 12:37:58) ---> System.TimeoutException: Waited for 00:00:15 but the command was not applied in this time." didn't occur anymore.

The next timeout was "IndexCreationException: Raven.Client.Exceptions.Documents.Indexes.IndexCreationException: Failed to create auto index: Auto/Feedbacks/ByState, the cluster is probably down. Node A state is Leader, I'm the only one in the cluster, so I'm the leader (at 15/03/2018 13:48:48) ---> System.TimeoutException: Waited for 00:00:30 for transaction write lock, but could not get it, the tx is currently owned by thread 20 - Consensus Leader - A in term 1, OS thread id: 12697", however reported to appear in a much lower rate which can be acceptable due to the nature of this slow I/O.

After this weekend, Adam should report how it worked with OperationTimeoutInSec=180.

. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .

Hibernating Rhinos Ltd                      
Avivi Adi l Core Team
Office: +972-4-622-7811 l Fax: +972-153-4-622-7811
RavenDB paving the way to "Data Made Simple"   http://ravendb.net

On Tue, Mar 13, 2018 at 2:36 PM, Adam Novák <adsa...@gmail.com> wrote:

yes