It takes much more time to gracefully shutdown

[sherlock-shi-x]

System information

Geth version: geth 1.9.14-stable geth 1.9.15-stable
OS & Version: Linux-Ubuntu-18.04

Expected behaviour

After using kill command (without -9) to realize the gracefully shutdown, the node will usually take several minutes to fullfil it.

Actual behaviour

It took much more time and I don't have the real duration time right now cuz I can't wait so much time.

It worked fine in old version, or at least before 1.9.13.

[holiman]

It can still take quite some time, however, we had one regression in this area -- see #21087 . Fixed here: #21114 -- so this should not be an issue as of 1.9.15. What times are you seeing with 1.9.15-stable ?

[sherlock-shi-x]

not be much certain about it, the version of go seems to affect it.
btw, I have shut it down gracefully with go-1.14.4

[pyggie]

In my experience with 1.9.15-stable on Linux, attempts to do a graceful shutdown (with kill -INT) fail close to half the time. Here is an example where it hung for 12 minutes before I killed it:

INFO [07-07|18:07:24.530] Imported new chain segment               blocks=1  txs=142  mgas=11.432  elapsed=204.086ms mgasps=56.015  number=10413888 hash="07fbdc…623da6" dirty=1.16GiB
INFO [07-07|18:08:00.490] Deep froze chain segment                 blocks=3  elapsed=29.468ms  number=10323887 hash="ea9e4e…1bc503"
INFO [07-07|18:08:33.645] Imported new chain segment               blocks=1  txs=219  mgas=11.445  elapsed=285.878ms mgasps=40.033  number=10413889 hash="ef4184…d6a5d5" age=1m9s  dirty=1.16GiB
INFO [07-07|18:08:36.592] Imported new chain segment               blocks=1  txs=148  mgas=11.445  elapsed=206.105ms mgasps=55.531  number=10413890 hash="6df938…414e97" dirty=1.16GiB
INFO [07-07|18:09:00.518] Deep froze chain segment                 blocks=2  elapsed=27.171ms  number=10323889 hash="9c028a…d8623a"
INFO [07-07|18:09:05.858] Imported new chain segment               blocks=1  txs=209  mgas=11.453  elapsed=264.543ms mgasps=43.292  number=10413891 hash="6bc225…7a5786" dirty=1.16GiB
INFO [07-07|18:09:35.854] Got interrupt, shutting down...
INFO [07-07|18:09:35.857] WebSocket endpoint closed                url=ws://127.0.0.1:8546
INFO [07-07|18:09:35.857] HTTP endpoint closed                     url=http://127.0.0.1:8545/
INFO [07-07|18:09:35.857] IPC endpoint closed                      url=/mnt/data/geth/geth.ipc
INFO [07-07|18:10:00.548] Deep froze chain segment                 blocks=1  elapsed=25.745ms  number=10323890 hash="f97e43…dc7cc3"
INFO [07-07|18:11:40.334] Regenerated local transaction journal    transactions=0 accounts=0
WARN [07-07|18:21:08.194] Already shutting down, interrupt more to panic. times=9
WARN [07-07|18:21:38.055] Already shutting down, interrupt more to panic. times=8
WARN [07-07|18:21:38.330] Already shutting down, interrupt more to panic. times=7
WARN [07-07|18:21:38.561] Already shutting down, interrupt more to panic. times=6
WARN [07-07|18:21:38.755] Already shutting down, interrupt more to panic. times=5
WARN [07-07|18:21:38.969] Already shutting down, interrupt more to panic. times=4
WARN [07-07|18:21:39.158] Already shutting down, interrupt more to panic. times=3
WARN [07-07|18:21:39.446] Already shutting down, interrupt more to panic. times=2
WARN [07-07|18:21:39.706] Already shutting down, interrupt more to panic. times=1
panic: boom

After this type of shutdown, geth needs to resync 12+ hours of blocks. Here is the start of the next log:

...
WARN [07-07|18:22:03.665] Head state missing, repairing chain      number=10413891 hash="6bc225…7a5786"
INFO [07-07|18:22:08.179] Rewound blockchain to past state         number=10409573 hash="45c1b9…7b0b34"
INFO [07-07|18:22:08.180] Loaded most recent local header          number=10413891 hash="6bc225…7a5786" td=16231628092636980686757 age=13m32s
INFO [07-07|18:22:08.181] Loaded most recent local full block      number=10409573 hash="45c1b9…7b0b34" td=16221582921520066392361 age=16h13m6s
INFO [07-07|18:22:08.181] Loaded most recent local fast block      number=10413891 hash="6bc225…7a5786" td=16231628092636980686757 age=13m32s
INFO [07-07|18:22:08.187] Regenerated local transaction journal    transactions=0 accounts=0
WARN [07-07|18:22:08.187] Switch sync mode from fast sync to full sync
...
INFO [07-07|18:22:35.253] Block synchronisation started
INFO [07-07|18:22:38.720] Looking for peers                        peercount=4 tried=50 static=0
INFO [07-07|18:22:46.053] Importing heavy sidechain segment        blocks=1748 start=10409574 end=10411321
INFO [07-07|18:22:48.735] Looking for peers                        peercount=6 tried=53 static=0
INFO [07-07|18:22:55.354] Imported new chain segment               blocks=7    txs=1129 mgas=83.824 elapsed=9.298s mgasps=9.014 number=10409580 hash="df460b…efe538" age=16h12m27s dirty=10.12MiB
INFO [07-07|18:22:58.756] Looking for peers                        peercount=7 tried=64 static=0
INFO [07-07|18:23:04.398] Imported new chain segment               blocks=9    txs=1612 mgas=107.734 elapsed=9.044s mgasps=11.911 number=10409589 hash="be8532…b9cce0" age=16h10m11s dirty=23.58MiB

The shutdown problem wouldn't be so bad if there were some way to tell geth it should persist the trie data to disk more frequently. Is there a way to trigger this via the admin interface?

[pyggie]

As a contrast, here is a successful graceful shutdown. Notice several messages that are missing from my previous comment: "Ethereum protocol stopped", "Transaction pool stopped", "Writing cached state to disk", etc.

INFO [07-07|18:46:49.369] Imported new chain segment               blocks=1    txs=161  mgas=11.685  elapsed=489.591ms mgasps=23.867 number=10414060 hash="f67e17…d5f503" dirty=1.20GiB
INFO [07-07|18:46:49.464] Got interrupt, shutting down...
INFO [07-07|18:46:49.465] WebSocket endpoint closed                url=ws://127.0.0.1:8546
INFO [07-07|18:46:49.467] HTTP endpoint closed                     url=http://127.0.0.1:8545/
INFO [07-07|18:46:49.467] IPC endpoint closed                      url=/mnt/data/geth/geth.ipc
INFO [07-07|18:46:50.283] Ethereum protocol stopped
INFO [07-07|18:46:51.551] Transaction pool stopped
INFO [07-07|18:46:51.551] Writing cached state to disk             block=10414060 hash="f67e17…d5f503" root="cdac03…34b3e3"
INFO [07-07|18:46:53.395] Looking for peers                        peercount=3  tried=110 static=0
INFO [07-07|18:47:03.396] Looking for peers                        peercount=1  tried=126 static=0
INFO [07-07|18:47:13.043] Deep froze chain segment                 blocks=6    elapsed=2.205s    number=10324059 hash="e42831…9eacc6"
INFO [07-07|18:47:13.495] Looking for peers                        peercount=0  tried=96  static=0
INFO [07-07|18:47:23.555] Looking for peers                        peercount=0  tried=89  static=0
INFO [07-07|18:47:33.715] Looking for peers                        peercount=0  tried=38  static=0
INFO [07-07|18:47:38.952] Persisted trie from memory database      nodes=3311178 size=771.17MiB time=54.864502019s gcnodes=10625002 gcsize=4.19GiB gctime=1m6.848151152s livenodes=301947 livesize=122.08MiB
INFO [07-07|18:47:38.952] Writing cached state to disk             block=10414059 hash="c74f92…d3da0f" root="fc2dc7…0d09e2"
INFO [07-07|18:47:39.001] Persisted trie from memory database      nodes=2811    size=1.13MiB   time=49.192309ms   gcnodes=0        gcsize=0.00B   gctime=0s             livenodes=299136 livesize=120.95MiB
INFO [07-07|18:47:39.001] Writing cached state to disk             block=10413933 hash="e83f59…231923" root="531dd1…8a453c"
INFO [07-07|18:47:42.101] Persisted trie from memory database      nodes=106837  size=42.34MiB  time=3.099705433s  gcnodes=0        gcsize=0.00B   gctime=0s             livenodes=192299 livesize=78.61MiB
INFO [07-07|18:47:42.947] Blockchain stopped
INFO [07-07|18:47:43.791] Looking for peers                        peercount=1  tried=73  static=0

[holiman]

If you still have the stack trace following the 'boom', then we might be able to figure it out...?

[pyggie]

I do, it's large, what is the best way to share?

[holiman]

Maybe pastebin or something similar? Or a github repo? 

[pyggie]

I created a gist for the panic log: https://gist.github.com/pyggie/e63de7001a07974b81c111f82a7f302e

[pyggie]

The next time I tried to stop this same geth instance, it hung again. During the shutdown process it reported "Submitted transaction" for some local transactions that were about an hour old. It never reported "Ethereum protocol stopped", "Transaction pool stopped", "Writing cached state to disk", etc. This time I let the shutdown process run for many hours (CPU load and network load remained high, disk load dropped) but it never completed:

INFO [07-09|08:35:04.334] Imported new chain segment               blocks=1  txs=193 mgas=11.892 elapsed=269.299ms mgasps=44.158  number=10424284 hash="603061…812cbd" dirty=1.08GiB
INFO [07-09|08:35:13.998] Imported new chain segment               blocks=1  txs=245 mgas=11.870 elapsed=257.851ms mgasps=46.033  number=10424285 hash="21969e…feaa73" dirty=1.08GiB
INFO [07-09|08:35:14.526] Deep froze chain segment                 blocks=6  elapsed=47.092ms  number=10334284 hash="3b0064…405c2b"
INFO [07-09|08:35:34.137] Imported new chain segment               blocks=1  txs=233 mgas=11.852 elapsed=3.725s    mgasps=3.181   number=10424286 hash="1e851c…f27647" dirty=1.08GiB
INFO [07-09|08:35:38.324] Got interrupt, shutting down...
INFO [07-09|08:35:38.330] WebSocket endpoint closed                url=ws://127.0.0.1:8546
INFO [07-09|08:35:38.336] HTTP endpoint closed                     url=http://127.0.0.1:8545/
INFO [07-09|08:35:38.337] IPC endpoint closed                      url=/mnt/data/geth/geth.ipc
INFO [07-09|08:35:38.618] Imported new chain segment               blocks=1  txs=169 mgas=11.819 elapsed=3.136s    mgasps=3.768   number=10424287 hash="830031…4ed9c7" dirty=1.08GiB
INFO [07-09|08:35:44.186] Submitted transaction                    fullhash=0x... recipient=0x...
INFO [07-09|08:35:44.187] Submitted transaction                    fullhash=0x... recipient=0x...
INFO [07-09|08:35:44.187] Submitted transaction                    fullhash=0x... recipient=0x...
INFO [07-09|08:36:14.553] Deep froze chain segment                 blocks=2  elapsed=27.038ms  number=10334286 hash="dbe99c…0acbd6"
INFO [07-09|08:56:18.618] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-09|09:56:18.657] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-09|10:56:18.636] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-09|11:56:18.683] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-09|12:56:18.694] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-09|13:56:18.617] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-09|14:56:18.598] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-09|15:56:18.665] Regenerated local transaction journal    transactions=0 accounts=0
WARN [07-09|16:01:27.385] Already shutting down, interrupt more to panic. times=9
WARN [07-09|16:01:34.931] Already shutting down, interrupt more to panic. times=8
WARN [07-09|16:01:35.298] Already shutting down, interrupt more to panic. times=7
WARN [07-09|16:01:35.651] Already shutting down, interrupt more to panic. times=6
WARN [07-09|16:01:35.962] Already shutting down, interrupt more to panic. times=5
WARN [07-09|16:01:36.350] Already shutting down, interrupt more to panic. times=4
WARN [07-09|16:01:36.716] Already shutting down, interrupt more to panic. times=3
WARN [07-09|16:01:37.095] Already shutting down, interrupt more to panic. times=2
WARN [07-09|16:01:37.440] Already shutting down, interrupt more to panic. times=1
panic: boom

Upon restart it needed to resync 21 hours of blocks:

...
WARN [07-09|16:02:20.290] Head state missing, repairing chain      number=10424287 hash="830031…4ed9c7"
INFO [07-09|16:02:25.355] Rewound blockchain to past state         number=10420582 hash="a18f55…90a05b"
INFO [07-09|16:02:25.356] Loaded most recent local header          number=10424287 hash="830031…4ed9c7" td=16256859510604898421154 age=7h26m55s
INFO [07-09|16:02:25.356] Loaded most recent local full block      number=10420582 hash="a18f55…90a05b" td=16247815226581652244543 age=21h11m52s
INFO [07-09|16:02:25.356] Loaded most recent local fast block      number=10424287 hash="830031…4ed9c7" td=16256859510604898421154 age=7h26m55s
INFO [07-09|16:02:25.357] Regenerated local transaction journal    transactions=0 accounts=0
WARN [07-09|16:02:25.357] Switch sync mode from fast sync to full sync
...
INFO [07-09|16:02:47.241] Imported new chain segment               blocks=5    txs=670 mgas=47.138 elapsed=9.101s mgasps=5.179 number=10420587 hash="403eed…132732" age=21h11m18s dirty=6.48MiB
INFO [07-09|16:02:55.360] Imported new chain segment               blocks=8    txs=1497 mgas=82.279 elapsed=8.118s mgasps=10.135 number=10420595 hash="0fedf2…672650" age=21h9m10s  dirty=17.34MiB
INFO [07-09|16:03:04.535] Imported new chain segment               blocks=9    txs=1629 mgas=105.345 elapsed=9.175s mgasps=11.481 number=10420604 hash="bb4cc5…e03648" age=21h5m36s  dirty=31.35MiB

As a workaround, is there any way I can ask geth to write the trie data to disk? Or increase the frequency that is done automatically?

[pyggie]

I added the boom stack trace for the second incident as a second file (geth.2.log) in the same gist:
https://gist.github.com/pyggie/e63de7001a07974b81c111f82a7f302e

[adamschmideg]

One more step for us: write a script that starts Geth and kills it after a few minutes and keeps repeating this.

[pyggie]

One more step for us: write a script that starts Geth and kills it after a few minutes and keeps repeating this.

Not sure I understand: Is something you would like me to do? And then post logs?