Slow execution (spurious idle-periods during startup)

[holiman]

This might not be an error at all, I'm just trying to figure out why evmtool is extremely slow on my machine, and I noticed the same/similar happening with besu too.

I compiled latest besu (at 2d7cdf0da4cf7dd2a5f7db5de750ef6358b0f73a), and ran it, like so, on a little 4-core NUC unit.

~/besu$ ./build/install/besu/bin/besu --logging=ALL
Setting logging level to ALL
2020-10-16 14:23:38.046+02:00 | main | INFO  | AltBN128PairingPrecompiledContract | Using native alt bn128
2020-10-16 14:27:03.520+02:00 | main | INFO  | SECP256K1 | Using native secp256k1

There is a four-minute gap between those lines, where seemingly nothing happens. There is almost no IO, there is almost zero processor use, and I have no idea what's going on. After that, things start happening at a rapid pace:

2020-10-16 14:23:38.046+02:00 | main | INFO  | AltBN128PairingPrecompiledContract | Using native alt bn128
2020-10-16 14:27:03.520+02:00 | main | INFO  | SECP256K1 | Using native secp256k1
2020-10-16 14:27:03.529+02:00 | main | INFO  | Besu | Starting Besu version: besu/v20.10.1-dev-2d7cdf0d/linux-x86_64/openjdk-java-14
2020-10-16 14:27:03.560+02:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.level: simple
2020-10-16 14:27:03.560+02:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.targetRecords: 4
2020-10-16 14:27:03.567+02:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2020-10-16 14:27:03.567+02:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2020-10-16 14:27:03.572+02:00 | main | DEBUG | MultithreadEventLoopGroup | -Dio.netty.eventLoopThreads: 8
2020-10-16 14:27:03.586+02:00 | main | DEBUG | NioEventLoop | -Dio.netty.noKeySetOptimization: false
2020-10-16 14:27:03.586+02:00 | main | DEBUG | NioEventLoop | -Dio.netty.selectorAutoRebuildThreshold: 512
2020-10-16 14:27:03.594+02:00 | main | DEBUG | PlatformDependent0 | -Dio.netty.noUnsafe: false
2020-10-16 14:27:03.595+02:00 | main | DEBUG | PlatformDependent0 | Java version: 14
2020-10-16 14:27:03.596+02:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.theUnsafe: available
2020-10-16 14:27:03.596+02:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.copyMemory: available
2020-10-16 14:27:03.597+02:00 | main | DEBUG | PlatformDependent0 | java.nio.Buffer.address: available
2020-10-16 14:27:03.597+02:00 | main | DEBUG | PlatformDependent0 | direct buffer constructor: available
2020-10-16 14:27:03.598+02:00 | main | DEBUG | PlatformDependent0 | java.nio.Bits.unaligned: available, true
2020-10-16 14:27:03.599+02:00 | main | DEBUG | PlatformDependent0 | jdk.internal.misc.Unsafe.allocateUninitializedArray(int): available
2020-10-16 14:27:03.599+02:00 | main | DEBUG | PlatformDependent0 | java.nio.DirectByteBuffer.<init>(long, int): available
2020-10-16 14:27:03.600+02:00 | main | DEBUG | PlatformDependent | sun.misc.Unsafe: available
2020-10-16 14:27:03.600+02:00 | main | DEBUG | PlatformDependent | maxDirectMemory: 8344567808 bytes (maybe)
2020-10-16 14:27:03.600+02:00 | main | DEBUG | PlatformDependent | -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
2020-10-16 14:27:03.600+02:00 | main | DEBUG | PlatformDependent | -Dio.netty.bitMode: 64 (sun.arch.data.model)
2020-10-16 14:27:03.601+02:00 | main | DEBUG | PlatformDependent | -Dio.netty.maxDirectMemory: 8344567808 bytes
2020-10-16 14:27:03.601+02:00 | main | DEBUG | PlatformDependent | -Dio.netty.uninitializedArrayAllocationThreshold: 1024
2020-10-16 14:27:03.602+02:00 | main | DEBUG | CleanerJava9 | java.nio.ByteBuffer.cleaner(): available
2020-10-16 14:27:03.602+02:00 | main | DEBUG | PlatformDependent | -Dio.netty.noPreferDirect: false
2020-10-16 14:27:03.607+02:00 | main | DEBUG | PlatformDependent | org.jctools-core.MpscChunkedArrayQueue: available

Running it a second time, it came up very quickly:

Setting logging level to ALL
2020-10-16 14:32:47.648+02:00 | main | INFO  | AltBN128PairingPrecompiledContract | Using native alt bn128
2020-10-16 14:32:48.228+02:00 | main | INFO  | SECP256K1 | Using native secp256k1
2020-10-16 14:32:48.233+02:00 | main | INFO  | Besu | Starting Besu version: besu/v20.10.1-dev-2d7cdf0d/linux-x86_64/openjdk-java-14

Running it a third time, it stalled for about 2 minutes again:

2020-10-16 14:32:55.522+02:00 | main | INFO  | AltBN128PairingPrecompiledContract | Using native alt bn128
2020-10-16 14:35:09.658+02:00 | main | INFO  | SECP256K1 | Using native secp256k1
2020-10-16 14:35:09.665+02:00 | main | INFO  | Besu | Starting Besu version: besu/v20.10.1-dev-2d7cdf0d/linux-x86_64/openjdk-java-14
2020-10-16 14:35:09.705+02:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.level: simple

Any idea what's going on here?

[holiman]

If I use

./build/install/besu/bin/besu --logging=ALL --Xsecp256k1-native-enabled false

Then I don't experience those idle-periods during boot. 🤷

[shemnon]

My guess is that the bitcoin core elliptic curve binary is blocking on native randomness, we've seen that in our acceptance tests with some of our acceptance tests on the java side. (secure by default, side channel attacks, yadda yadda yadda).

To turn off this randomization set either JAVA_OPTS or BESU_OPTS environmental variables to
-Dsecp256k1.randomize=false - this will tell the library integration to skip the randomization step. Since it's test code this should be fine, but the standard disclaimer of "you shouldn't do this in production signing real money transactions" applies.

[holiman]

Yes, that does fix the idle-period.

[holiman]

Heh, the evm execution went from 3-5 minutes down to a couple of seconds 👍

[shemnon]

I think I'll make it standard for EVMTool since it's non-production.

[holiman]

Running them in a batch, I now did 10K statetests in 5 minutes. As far as I'm concerned, this issue can be closed, but I'll leave it open if you want to have it as a reminder to fix the standard.
It seems very odd, btw, why the random should be starved. It's a standard Ubuntu 20.04.1 LTS running on an intel NUC. It's running an X-server, dunno if java magic tries to tweak out bits of random from some UI-components.

[holiman]

This also works, and may be a better solution: "-Djava.security.egd=file:/dev/./urandom". Some people will tell you that urandom isn't good enough, but here's what Thomas Ptacek has to say about it: https://sockpuppet.org/blog/2014/02/25/safely-generate-random-numbers/

Use urandom

Use urandom. Use urandom. Use urandom. Use urandom. Use urandom. Use urandom.
But what about for crypto keys?

Still urandom.

[shemnon]

We've still seen that solution block as well, it was one of our first attempts. Also, that won't propagate down into the native secp256k1 code, only java managed encryption.

[ajsutton]

Note that in Besu's (then Pantheon) first audit, one of the issues was that we were using /dev/random and the recommendation was to use /dev/urandom by default. So assuming -Dsecp256k1.randomize=false does map to use /dev/urandom instead of /dev/random then enabling it by default is likely the more secure option. Especially since users could deliberately target Besu and attempt to exhaust entropy by submitting a lot of transactions that use these precompiles.

But this is a drive by comment so feel free to ignore as I may be missing some context. :)

[holiman]

This would explain two other things -- a lot of hive failures are due to timeouts, e.g. this one: https://hivetests.ethdevops.io/viewer.html?file=results/besu_latest/client-0bc3fcf2.log . Apparently the idle-period makes it time out.
It would also explain why the hive execution takes 2+ days for besu. Even in the cases where it doesn't time out, if it adds 30 seconds to the executions of 12K, it adds up.

[shemnon]

--Dsecp256k1.randomize=false turns off the secp256k1 seed randomization, it doesn't make it use different entropy. It makes it vulnerable to side channel attacks. So it should default to on for production but for consensus testing all the keys are already known. And since Besu doesn't do wallets the only real value it provides is related to the node key.