Skip to content

Imported new potential chain segment poor performance when ancient is on external drive — v1.13.5 #28534

@adamgall

Description

@adamgall

System information

Geth version:

$ geth --version
geth version 1.13.5-stable-916d6a44

CL client & version:

$ lighthouse --version
Lighthouse v4.5.0-441fc16
BLS library: blst
SHA256 hardware acceleration: true
Allocator: jemalloc
Profile: maxperf
Specs: mainnet (true), minimal (false), gnosis (false)

OS & Version:

$ uname -a
Linux nuc 5.15.0-88-generic #98-Ubuntu SMP Mon Oct 2 15:18:56 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.3 LTS
Release:        22.04
Codename:       jammy

Expected behaviour

Typical high-performant attestation behavior.

Actual behaviour

Much higher than usual instances of:

  • missed attestations
  • attestations being included in late blocks
  • attestations not voting on the correct chain head

Steps to reproduce the behaviour

Run geth on version 1.13.5

Startup command

[Unit]
Description=Geth Execution Client
Wants=network-online.target
After=network-online.target

[Service]
User=geth
Group=geth

Type=simple
Restart=always

ExecStart=/usr/local/bin/geth \
        --datadir=/var/lib/geth \
        --port=30303 \
        --http=true \
        --http.port=8545 \
        --authrpc.jwtsecret=/var/lib/ethereum-shared/jwt-primary.hex \
        --authrpc.port=8551 \
        --db.engine=pebble \
        --state.scheme=path \

[Install]
WantedBy=multi-user.target

Backtrace

INFO [11-15|20:15:36.780] Imported new potential chain segment     number=18,579,606 hash=dbab5c..37f2c0 blocks=1 txs=185 mgas=16.103 elapsed=150.738ms   mgasps=106.828 snapdiffs=5.99MiB triediffs=178.01MiB triedirty=12.25MiB
INFO [11-15|20:15:36.910] Chain head was updated                   number=18,579,606 hash=dbab5c..37f2c0 root=29d20e..e2074f elapsed=2.483595ms
INFO [11-15|20:15:49.853] Imported new potential chain segment     number=18,579,607 hash=f712d1..aa7e0a blocks=1 txs=137 mgas=15.814 elapsed=1.138s      mgasps=13.892  snapdiffs=6.04MiB triediffs=178.04MiB triedirty=12.82MiB
INFO [11-15|20:15:49.992] Chain head was updated                   number=18,579,607 hash=f712d1..aa7e0a root=85bf19..16d40f elapsed=3.660048ms
INFO [11-15|20:16:02.419] Imported new potential chain segment     number=18,579,608 hash=ecba4e..265465 blocks=1 txs=126 mgas=13.707 elapsed=1.984s      mgasps=6.905   snapdiffs=6.07MiB triediffs=177.81MiB triedirty=13.24MiB
INFO [11-15|20:16:02.592] Chain head was updated                   number=18,579,608 hash=ecba4e..265465 root=0aadca..cab0b8 elapsed=3.509709ms
INFO [11-15|20:16:16.972] Imported new potential chain segment     number=18,579,609 hash=d92259..820503 blocks=1 txs=214 mgas=22.833 elapsed=2.050s      mgasps=11.135  snapdiffs=6.11MiB triediffs=178.43MiB triedirty=13.67MiB
INFO [11-15|20:16:17.131] Chain head was updated                   number=18,579,609 hash=d92259..820503 root=69fa1b..8cc8ed elapsed=3.917986ms
INFO [11-15|20:16:26.642] Imported new potential chain segment     number=18,579,610 hash=66882a..6c500f blocks=1 txs=117 mgas=10.856 elapsed=2.011s      mgasps=5.397   snapdiffs=6.15MiB triediffs=178.37MiB triedirty=14.08MiB
INFO [11-15|20:16:26.776] Chain head was updated                   number=18,579,610 hash=66882a..6c500f root=6c299b..ccd5ff elapsed=2.88514ms
INFO [11-15|20:16:38.755] Imported new potential chain segment     number=18,579,611 hash=972d8c..06f8dd blocks=1 txs=141 mgas=10.532 elapsed=1.931s      mgasps=5.453   snapdiffs=6.18MiB triediffs=178.29MiB triedirty=14.47MiB
INFO [11-15|20:16:38.947] Chain head was updated                   number=18,579,611 hash=972d8c..06f8dd root=fd3463..1c5048 elapsed=2.612727ms
INFO [11-15|20:16:50.525] Imported new potential chain segment     number=18,579,612 hash=2f1817..fbc1b5 blocks=1 txs=188 mgas=13.286 elapsed=2.107s      mgasps=6.305   snapdiffs=6.22MiB triediffs=178.40MiB triedirty=15.02MiB
INFO [11-15|20:16:50.663] Chain head was updated                   number=18,579,612 hash=2f1817..fbc1b5 root=bec5ce..3c5e22 elapsed=3.444437ms
INFO [11-15|20:17:01.373] Imported new potential chain segment     number=18,579,613 hash=037f6b..9a1169 blocks=1 txs=135 mgas=11.636 elapsed=933.221ms   mgasps=12.469  snapdiffs=6.26MiB triediffs=178.21MiB triedirty=15.55MiB
INFO [11-15|20:17:01.509] Chain head was updated                   number=18,579,613 hash=037f6b..9a1169 root=255985..95ccee elapsed=2.088793ms
INFO [11-15|20:17:12.655] Imported new potential chain segment     number=18,579,614 hash=689b77..3533fa blocks=1 txs=216 mgas=16.396 elapsed=184.686ms   mgasps=88.777  snapdiffs=6.30MiB triediffs=178.65MiB triedirty=15.97MiB
INFO [11-15|20:17:12.772] Chain head was updated                   number=18,579,614 hash=689b77..3533fa root=081983..580735 elapsed=3.296078ms
INFO [11-15|20:17:25.151] Imported new potential chain segment     number=18,579,615 hash=0df623..47a13a blocks=1 txs=138 mgas=14.496 elapsed=189.998ms   mgasps=76.296  snapdiffs=6.34MiB triediffs=178.73MiB triedirty=16.38MiB
INFO [11-15|20:17:25.285] Chain head was updated                   number=18,579,615 hash=0df623..47a13a root=6e09f5..49b456 elapsed=4.620928ms
INFO [11-15|20:17:38.091] Imported new potential chain segment     number=18,579,616 hash=78bc61..c2c488 blocks=1 txs=206 mgas=18.955 elapsed=204.642ms   mgasps=92.626  snapdiffs=6.39MiB triediffs=179.20MiB triedirty=16.74MiB
INFO [11-15|20:17:38.212] Chain head was updated                   number=18,579,616 hash=78bc61..c2c488 root=6ebe99..9df013 elapsed=2.753035ms
INFO [11-15|20:17:51.712] Imported new potential chain segment     number=18,579,617 hash=2cf10c..a8c0a9 blocks=1 txs=145 mgas=14.961 elapsed=1.137s      mgasps=13.148  snapdiffs=6.43MiB triediffs=179.38MiB triedirty=17.16MiB
INFO [11-15|20:17:51.861] Chain head was updated                   number=18,579,617 hash=2cf10c..a8c0a9 root=cbf2f6..079f30 elapsed=4.30093ms
INFO [11-15|20:18:04.540] Imported new potential chain segment     number=18,579,618 hash=c4b4b0..dbc556 blocks=1 txs=152 mgas=23.963 elapsed=2.023s      mgasps=11.844  snapdiffs=6.47MiB triediffs=179.80MiB triedirty=17.44MiB
INFO [11-15|20:18:04.670] Chain head was updated                   number=18,579,618 hash=c4b4b0..dbc556 root=4d75ec..b2f8e8 elapsed=5.809166ms
INFO [11-15|20:18:14.677] Imported new potential chain segment     number=18,579,619 hash=915087..1d32d9 blocks=1 txs=149 mgas=14.145 elapsed=2.041s      mgasps=6.928   snapdiffs=6.50MiB triediffs=179.93MiB triedirty=17.81MiB
INFO [11-15|20:18:14.792] Chain head was updated                   number=18,579,619 hash=915087..1d32d9 root=c87184..be711b elapsed=3.238122ms
INFO [11-15|20:18:26.486] Imported new potential chain segment     number=18,579,620 hash=f14a75..03ced5 blocks=1 txs=254 mgas=15.461 elapsed=1.994s      mgasps=7.750   snapdiffs=6.54MiB triediffs=180.31MiB triedirty=18.14MiB
INFO [11-15|20:18:26.602] Chain head was updated                   number=18,579,620 hash=f14a75..03ced5 root=ee9481..28f946 elapsed=3.521982ms

Looking at the logs, it seems like there are periods where the elapsed time on "Imported new potential chain segment" logs are on the order of seconds. These periods last for a few slots, then go back to "normal" processing times (on the order of 1-200ms) for a few slots, then repeat.

I suspect that it's these periods of "slow" chain segmet processing times that are leading to poor attestation performance, but that's an assumption. That is the only difference I can see between the logs of 1.13.5, vs 1.13.4 (apart from no more "Peer delivering stale transaction" logs!)

This slow chain segment processing issue (assuming it's the culprit for poor attestation performance) was not occurring on my machine when running version 1.13.4.

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions