Java running out of memory? & More data base error about bitcoin-verde HOT 15 CLOSED

So I got the node to start syncing again after killing the mysql process, but as a result the node restarted from the 0%...Let's see if this persists

from bitcoin-verde.

Yeah so the issue still persists. It failed over the weekend and again today, on a fresh install.

OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000ff200000, 3145728, 0) failed; error='Cannot allocate memory' (errno=12)
```. 

After which, cannot restart the node due to data base error

from bitcoin-verde.

Thanks for the report, Apollo! Couple of questions: did you compile the native utxo cache before building the node jarfile? (cd jni/utxo-cache && ./scripts/make.sh && ./scripts/copy-bin.sh)? What is the bitcoin.maxUtxoCacheByteCount and bitcoin.database.maxMemoryByteCount value set to in your out/conf/server.conf?

Using the native utxo cache isn't mandatory, but will tell me if the node is using the java version (which isn't a highly-tested component, so I wouldn't be surprised if it's not shrinking its memory correctly).

Regarding the /scripts/run-repair.sh script: I love that you found this script, and thought to use it. It doesn't do quite what you think (and it's my fault for not putting its (sparse) documentation in a more readily-findable place).

If you run ./scripts/run-jar.sh it'll display the help dialog, where the repair command documentation is hidden.

	Module: REPAIR
	Arguments: <Configuration File> <Block Hash> [<Block Hash> [...]]
	Description: Downloads the requested blocks and repairs the database with the blocks received from the configured trusted peer.
	Argument Description: <Configuration File>
		The path and filename of the configuration file for running the node.  Ex: conf/server.conf
	Argument Description: <Block Hash>
		The block that should be repaired. Multiple blocks may be specified, each separated by a space.
		Ex: 000000000019D6689C085AE165831E934FF763AE46A2A6C172B3F1B60A8CE26F 000000000019D6689C085AE165831E934FF763AE46A2A6C172B3F1B60A8CE26F

So, while this could probably be used for the initial sync, it's probably not the fastest or most efficient. Its intent was to redownload and validate a corrupted block. (e.g. you can corrupt a block by manually writing to the database since the blocks are reinflated via the database and not stored on disk.)

So I got the node to start syncing again after killing the mysql process, but as a result the node restarted from the 0%...Let's see if this persists

The mysql process not dying is an unfortunate bug that exists in MariaDB4j; it's on my list of things to investigate and fix--it's plagued me for a bit now, unfortunately.

However, I am quite surprised it started at 0%. Now, it might have corrupted the transaction_bloom_filter, which would cause it to have do a full table scan to rebuild it, but that's not the same as 0% chain synchronization. The only scenario I can think of that would cause the chain to reset is if you ran ./scripts/make.sh-- you didn't do that by chance, right? (It overwrites the out directory completely.)

The transaction_bloom_filter recreation would look like this in the logs. Let me know if this is what you saw:

[2019-05-14 15:41:31] [NodeModule.java:737] [Loading Tx Bloom Filter]
[2019-05-14 15:41:31] [TransactionDatabaseManager.java:110] Rebuilding ExistingTransactionFilter. Filter TransactionHash: 38239F4F7F5276B1E674A47732756DBCE9336808D1FA2F5B3EF7CB454D9826B9, Database TransactionHash: EC0D4AB9A0421ADD49727239B2F677F54DB8A865A4E7F998CDFFF01573F10064
[2019-05-14 15:41:31] [TransactionDatabaseManager.java:118] [Building TransactionBloomFilter]

Also different would be rebuilding the utxo cache which happens after every restart. That looks something like this:

[2019-05-20 00:26:31] [BitcoinVerdeDatabase.java:53] [Initializing Database]
[2019-05-20 00:26:35] [NodeModule.java:287] [Database Online]
[2019-05-20 00:26:35] [MasterDatabaseManagerCache.java:43] NativeUnspentTransactionOutputCache max item count: 3391958
[2019-05-20 00:26:35] [NodeModule.java:365] [Loading RequestDataHandlerMonitor]
[2019-05-20 00:26:36] [SynchronizationStatusHandler.java:30] Synchronization State: SYNCHRONIZING
[2019-05-20 00:26:36] [NodeModule.java:120] [Warming Cache]
[2019-05-20 00:26:36] [CacheWarmer.java:77] Cached: 769908709 - 769904101 (4096 of 3391958) (0.12075622%) (36.027156ms)
[2019-05-20 00:26:36] [CacheWarmer.java:77] Cached: 769904100 - 769897628 (8192 of 3391958) (0.24151243%) (23.470048ms)
[2019-05-20 00:26:36] [CacheWarmer.java:77] Cached: 769897626 - 769889882 (12288 of 3391958) (0.36226863%) (19.788596ms)
[2019-05-20 00:26:36] [CacheWarmer.java:77] Cached: 769889880 - 769882040 (16384 of 3391958) (0.48302487%) (20.276588ms)

The memory issue you're encountering definitely smells like the utxo-cache is not behaving. Let me know what those two settings are and then I can look into it.

Finally, thanks for your patience, Apollo!

from bitcoin-verde.

Hey Josh, thanks for the detailed reply.

No I did not compile the native utxo cache before building.

I have tested with:
bitcoin.maxUtxoCacheByteCount = 0 (this seems to be the default number upon installation) & = 536870912 (Default indicated by documentation)
bitcoin.database.maxMemoryByteCount = 2147483648

Yes I did re-run the make.sh script knowing that it will erase everything since nothing else was working xD.

I’m going to try to run this on a linux instance since I couldn’t run the scripts (cd jni/utxo-cache && ./scripts/make.sh && ./scripts/copy-bin.sh)

from bitcoin-verde.

It's my pleasure, Apollo.

The native utxo cache should just require the build-essential packages on linux. The binary will be platform-specific obviously, so be sure you're building it on the same OS flavor as your server (which I believe is Ubuntu, correct?).

With your 4GB of memory, the settings you have should be close to okay; I'd probably advise ensuring bitcoin.useTransactionBloomFilter is still set to 0 (which is the default), since it'll use ~1GB of memory on its own.

Regardless, I'm pretty sure my original suspicion regarding the utxo-cache is not correct; looking at the master version, it's actually disabled. So now I believe there's just a bug in the java implementation of the MemoryConscientiousCache. I remember there was one from a while ago, but I thought I had fixed it--but apparently not. I'll reinvestigate (again, thank you for the issue/report).

In the meanwhile, using the native utxo-cache will probably not fix your problem--and will probably make it worse. Instead, I recommend editing com.softwareverde.bitcoin.server.database.cache.MasterDatabaseManagerCache and either disable the caches using com.softwareverde.bitcoin.server.database.cache.DisabledCache, or set their memoryPercentThreshold to something less than 95%, or reducing the cacheSize to something smaller (or both).

I created a branch you can use that will disable the caches--feel free to use this branch; if you do, let me know, because it'll help verify that that is where the problem lives and not somewhere else. Without the caches then things will definitely be slower, but will definitely help to pinpoint the problem. Branch is bug/0004_java_cache_out_of_memory. Assuming you're on master already, git fetch origin && git checkout bug/0004_java_cache_out_of_memory && ./scripts/make-jar.sh should suffice.

Let me know! I'll get to investigating and see if there's anything I can find.

from bitcoin-verde.

Thanks man!

Okay so I tried the branch and after about ~15% sync got the allocation memory error again. This is still ubuntu. Will try an linux instance now.

OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x00007f184aafb000, 12288, 0) failed; error='Cannot allocate memory' (errno=12)OpenJDK 64-Bit Server VM warning:
INFO: os::commit_memory(0x00007f18509f9000, 12288, 0) failed; error='Cannot allocate memory' (errno=12)OpenJDK 64-Bit Server VM warning:
OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x00007f1875073000, 12288, 0) failed; error='Cannot allocate memory' (errno=12)INFO: os::commit_memory(0x00007f184f7e7000, 12288, 0) failed; error='Cannot allocate memory' (errno=12)
OpenJDK 64-Bit Server VM warning:
INFO: os::commit_memory(0x00007f184dbcb000, 12288, 0) failed; error='Cannot allocate memory' (errno=12)OpenJDK 64-Bit Server VM warning:
INFO: os::commit_memory(0x00007f1850afa000, 12288, 0) failed; error='Cannot allocate memory' (errno=12)
OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x00007fb22022d000, 12288, 0) failed; error='Cannot allocate memory' (errno=12)
./scripts/run-node.sh: line 4: 12761 Aborted                 ./run-node.sh

from bitcoin-verde.

Yup so just tried this on a regular linux instance too and got the same error, but much much faster:

OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000fee00000, 3145728, 0) failed; error='Cannot allocate memory' (errno=12)
#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 3145728 bytes for committing reserved memory.
# An error report file with more information is saved as:
# /home/ec2-user/bitcoin-verde/out/hs_err_pid1786.log
[2019-05-23 20:31:38] [BitcoinNode.java:367] Received: BLOCK from 67.149.69.39:8333
[2019-05-23 20:31:38] [BitcoinNodeManager.java:437] Received Block: 00000000D8738058A2623A01712488226F7C2C0F0465B3083CE4F78D42C79635 from Node: 67.149.69.39:8333
[2019-05-23 20:31:38] [BlockDownloader.java:254] Downloaded Block: 00000000D8738058A2623A01712488226F7C2C0F0465B3083CE4F78D42C79635 (203ms)
[2019-05-23 20:31:38] [BitcoinNode.java:367] Received: BLOCK from 24.192.60.220:8333
[2019-05-23 20:31:38] [BitcoinNodeManager.java:437] Received Block: 0000000020C385EFB05BD1A41AD9B3F27BCBF7A323088F9498629049EDE86097 from Node: 24.192.60.220:8333
[2019-05-23 20:31:38] [BlockDownloader.java:254] Downloaded Block: 0000000020C385EFB05BD1A41AD9B3F27BCBF7A323088F9498629049EDE86097 (76ms)```

from bitcoin-verde.

I spun up an instance with the same settings as yours, and it is currently syncing. I think being able to tinker with the server myself will help me figure out what is going on. Hopefully I'll encounter the same error. I have time tomorrow to investigate after my VM explodes sometime tonight, so I'll let you know what I find.

from bitcoin-verde.

from bitcoin-verde.

Let me know how the swap goes, Apollo. It's certainly going to slow things down if it's swapping active memory to disk, but is still a good science experiment.

I believe the issue to be that MariaDB's memory footprint is getting far too large. I reran one of my tests with the database configured to only consume 1GB and it seems to be blatantly ignoring me; at the time of the crash it was consuming 70% of the system's memory--and even after the crash this is still true (since it doesn't close after the JVM explodes). I was fortunately able to connect to the database and check if it's simply running a large query or something, but it is not.

I don't have an immediate solution (yet, but I'm still working on it) other than "add more ram". Bitcoin Verde is meant to be an indexing node ran on a dedicated server, but I don't see why it can't run on a more memory constrained environment (it just wouldn't be ideal). So I'm going to keep investigating. I believe the error has little to do with the Java code itself, and now is simply becoming a matter of configuring the database correctly.

from bitcoin-verde.

@ApolloMuses , I think I've fixed it. I pushed a commit to the bug/0004_java_cache_out_of_memory branch earlier today and let it run. It seems to be behaving correctly now. Basically, the database wasn't being configured correctly and was allocating an additional GB of memory to the transaction log buffer.

The new branch also includes some updates from development, which should also prevent the sync stalling issue you encountered earlier on.

Let me know how it goes, and if yours is fixed like mine is, then I'll reenable the caches, let it run one more time, and then if all goes well merge into development and close the issue.

from bitcoin-verde.

I let the instance run with the caches re-enabled and memory usage seemed to fit the configured amount. Hopefully you have the same results.

from bitcoin-verde.

Hey Josh,

I had let the instance run over the weekend, and it did not have any memory issues after i changed the swap file to 8gb. Having said that, the syncing stalls at ~37%. While it doesn't crash anymore but the node doesn't seem to sync past this point

Any ideas?

from bitcoin-verde.

Here are some logs:

[2019-05-27 23:27:03] [NodeModule.java:821] Current Memory Usage: 123732032 bytes | MAX=1019215872 TOTAL=140509184 FREE=16777152
[2019-05-27 23:27:03] [NodeModule.java:822] Utxo Cache Hit: 0 vs 0 (NaN%)
[2019-05-27 23:27:03] [NodeModule.java:823] ThreadPool Queue: 0 | Active Thread Count: 0
[2019-05-27 23:27:03] [NodeModule.java:825] Alive Connections Count: 10
[2019-05-27 23:27:03] [NodeModule.java:826] Buffered Connections Count: 10
[2019-05-27 23:27:03] [NodeModule.java:827] In-Use Connections Count: 0

from bitcoin-verde.

There are a few things that could cause the sync the stall--the most predominant reason should be fixed during a merge I made this thread. I encourage you to try a rebuild, and let me know if you're still encountering the sync stall.

Since you're not encountering the out of memory error anymore I'm going to close this issue as resolved. If the rebuild doesn't solve the sync stalling, open a new issue and we can work from there. Sound fair?

Thanks again for taking the time to set up a node, and thanks for reporting this issue--it helped us to find that database configuration bug. I appreciate it.

from bitcoin-verde.