Improve DAO state store persistence and statistics logging [chimp1984]

[ghost]

The first commit in this PR (9378fe4) , written by @chimp1984, aims to improve the persistence of DAO state store files.

The motivation was from several user issues (#5929, #5917, #5925, #5934) which cropped up during the upgrade from 1.7.5 to 1.8.0. Each log file provided in the issues showed an error during the persistence of DAO state store files while shutting down v1.7.5 (likely timing related) which then caused a problem of corrupted DAO state files manifested when v1.8.0 started up. The resolution for that is to delete both DAO state files and let them be regenerated by the app at startup.

I have not managed to reproduce the users' issue, but I have tested this PR over several days, both regtest and mainnet. The types of test performed were:

• SPV resync
• restore from seed
• repeated startup & shutdown
• new user sync
• leave running for extended periods & observe
• generate blocks

The second commit (0b66fdc) changes the stats logging to include the count of threads and adjust the frequency of logging from 5 minutes to 1 hour. This change of frequency is requested by myself after checking many logs over the past 12 months the connection statistics being repeated every 5 minutes was too frequent, getting in the way of being able to read the log efficiently.

Here is an example of the statistics logging:

Dec-23 17:38:29.879 [JavaFX Application Thread] INFO  b.n.p2p.peers.PeerManager: Connection statistics: 

Connection 1
Age: 3 hours, 58 minutes, 59.264 seconds
Peer: x7z5tvdcqqq6z5hat33qsj6qxyuglkv3ay2emsmugi2afjninufmbyad.onion:9999 
Type: PEER 
Direction: Outbound
UID: c3756e7b-b151-4be0-b071-0cb0e78a1233
Time since last message: 1.536 seconds
Sent data: 4.226 MB; {AddDataMessage=1630, NewDaoStateHashMessage=30, AddPersistableNetworkPayloadMessage=153, RefreshOfferMessage=8106, RemoveDataMessage=96, NewBlockBroadcastMessage=23, GetPeersRequest=1, RemoveMailboxDataMessage=31, BundleOfEnvelopes=1830}
Received data: 4.58 MB; {AddDataMessage=1746, NewDaoStateHashMessage=29, AddPersistableNetworkPayloadMessage=190, GetPeersResponse=1, RefreshOfferMessage=8953, RemoveDataMessage=106, NewBlockBroadcastMessage=23, RemoveMailboxDataMessage=36}
CPU time spent on sending messages: 2.818 seconds
CPU time spent on receiving messages: 26.082 seconds

Connection 2
Age: 3 hours, 58 minutes, 57.752 seconds
Peer: s65qzl3rk2o4q4vk4q7tj7dt34caj7izzkyoehrydqczqnz73jdoorid.onion:9999 
Type: PEER 
Direction: Outbound
UID: 814ffab5-934d-41a2-8b77-56337a478fd8
Time since last message: 1.162 seconds
Sent data: 4.212 MB; {AddDataMessage=1625, NewDaoStateHashMessage=30, AddPersistableNetworkPayloadMessage=175, RefreshOfferMessage=8387, RemoveDataMessage=99, NewBlockBroadcastMessage=23, GetPeersRequest=1, RemoveMailboxDataMessage=16, BundleOfEnvelopes=1846}
Received data: 3.616 MB; {AddDataMessage=1381, NewDaoStateHashMessage=29, AddPersistableNetworkPayloadMessage=130, GetPeersResponse=1, RefreshOfferMessage=6906, NewBlockBroadcastMessage=21, RemoveDataMessage=91, RemoveMailboxDataMessage=30}
CPU time spent on sending messages: 1.751 seconds
CPU time spent on receiving messages: 16.251 seconds

Connection 3
Age: 3 hours, 58 minutes, 51.209 seconds
Peer: 3rra3cwkvsxjry47fkwp7vgxgp3r3nequq6ra6rynpmibh5agn4w6fqd.onion:9999 
Type: PEER 
Direction: Outbound
UID: c9052c04-f936-4bf3-8d01-4dc122377518
Time since last message: 2.254 seconds
Sent data: 4.282 MB; {AddDataMessage=1622, NewDaoStateHashMessage=29, AddPersistableNetworkPayloadMessage=160, RefreshOfferMessage=8218, RemoveDataMessage=109, NewBlockBroadcastMessage=29, GetPeersRequest=1, RemoveMailboxDataMessage=43, BundleOfEnvelopes=1841}
Received data: 3.529 MB; {AddDataMessage=1327, NewDaoStateHashMessage=29, AddPersistableNetworkPayloadMessage=162, GetPeersResponse=1, RefreshOfferMessage=7029, RemoveDataMessage=92, NewBlockBroadcastMessage=18, RemoveMailboxDataMessage=24}
CPU time spent on sending messages: 2.618 seconds
CPU time spent on receiving messages: 20.609 seconds

Connection 4
Age: 3 hours, 58 minutes, 44.986 seconds
Peer: icgsh6tgf3jf764l65uelqduc3zxvftuld35h74tgwuqugblphngk7qd.onion:9999 
Type: PEER 
Direction: Outbound
UID: 30f2a431-dc9d-4bb3-96a3-a61203533e8d
Time since last message: 2.042 seconds
Sent data: 4.436 MB; {AddDataMessage=1712, NewDaoStateHashMessage=29, AddPersistableNetworkPayloadMessage=162, RefreshOfferMessage=8534, RemoveDataMessage=113, NewBlockBroadcastMessage=27, GetPeersRequest=1, RemoveMailboxDataMessage=20, BundleOfEnvelopes=1901}
Received data: 3.773 MB; {AddDataMessage=1413, NewDaoStateHashMessage=29, AddPersistableNetworkPayloadMessage=127, GetPeersResponse=1, RefreshOfferMessage=7370, RemoveDataMessage=99, NewBlockBroadcastMessage=22, RemoveMailboxDataMessage=37}
CPU time spent on sending messages: 1.819 seconds
CPU time spent on receiving messages: 14.028 seconds

Connection 5
Age: 3 hours, 58 minutes, 25.881 seconds
Peer: 2xcyvtyqqgcxrsrrucvg6kikppqxoj622aqw3b7nysson4an5xsufkid.onion:9999 
Type: PEER 
Direction: Outbound
UID: 254db17f-0da0-48e0-b03a-d7c1b6539b92
Time since last message: 1.357 seconds
Sent data: 3.887 MB; {AddDataMessage=1387, NewDaoStateHashMessage=29, AddPersistableNetworkPayloadMessage=155, RefreshOfferMessage=8304, RemoveDataMessage=106, NewBlockBroadcastMessage=29, GetPeersRequest=1, RemoveMailboxDataMessage=34, BundleOfEnvelopes=1834}
Received data: 3.767 MB; {AddDataMessage=1485, AddPersistableNetworkPayloadMessage=150, GetPeersResponse=1, RefreshOfferMessage=7264, RemoveDataMessage=78, RemoveMailboxDataMessage=10}
CPU time spent on sending messages: 2.070 seconds
CPU time spent on receiving messages: 18.766 seconds

Connection 6
Age: 2 hours, 54 minutes, 56.227 seconds
Peer: fy25nlv6pphjvacqjvzm7kpjbwmiagx22aph7sdqyzwxw76qplzadqad.onion:9999 
Type: PEER 
Direction: Inbound
UID: bc96dd0f-91b0-4a9d-bf41-256bdf0b83e0
Time since last message: 1.616 seconds
Sent data: 3.128 MB; {AddDataMessage=1215, NewDaoStateHashMessage=22, AddPersistableNetworkPayloadMessage=125, GetPeersResponse=1, RefreshOfferMessage=6132, RemoveDataMessage=67, NewBlockBroadcastMessage=21, RemoveMailboxDataMessage=10, BundleOfEnvelopes=1361}
Received data: 3.322 MB; {AddDataMessage=1291, NewDaoStateHashMessage=22, AddPersistableNetworkPayloadMessage=117, RefreshOfferMessage=6557, RemoveDataMessage=67, NewBlockBroadcastMessage=21, GetPeersRequest=1, RemoveMailboxDataMessage=15}
CPU time spent on sending messages: 1.308 seconds
CPU time spent on receiving messages: 13.962 seconds

Connection 7
Age: 57 minutes, 31.993 seconds
Peer: awfnnb67kg7xv5gn62q5kkgetsn5cefu2czirnk4lrpsfszuopubrnqd.onion:9999 
Type: PEER 
Direction: Outbound
UID: 2edb6527-bb01-43c7-a621-64043913c7c3
Time since last message: 1.764 seconds
Sent data: 1.136 MB; {AddDataMessage=443, NewDaoStateHashMessage=8, AddPersistableNetworkPayloadMessage=45, RefreshOfferMessage=2411, RemoveDataMessage=23, NewBlockBroadcastMessage=7, GetPeersRequest=1, RemoveMailboxDataMessage=2, BundleOfEnvelopes=498}
Received data: 689.273 kB; {AddDataMessage=254, NewDaoStateHashMessage=8, AddPersistableNetworkPayloadMessage=26, GetPeersResponse=1, RefreshOfferMessage=1553, RemoveDataMessage=15, NewBlockBroadcastMessage=7}
CPU time spent on sending messages: 0.271 seconds
CPU time spent on receiving messages: 4.983 seconds

Connection 8
Age: 37 minutes, 32.361 seconds
Peer: aswlhotqhgfaicl22x6ijplv3disrxyxg3boegytb3j6q2cebqhqkkid.onion:9999 
Type: PEER 
Direction: Outbound
UID: 10b3d3e7-e769-4964-a6f8-36880af66027
Time since last message: 1.861 seconds
Sent data: 697.281 kB; {AddDataMessage=273, NewDaoStateHashMessage=6, AddPersistableNetworkPayloadMessage=22, RefreshOfferMessage=1343, RemoveDataMessage=15, NewBlockBroadcastMessage=4, GetPeersRequest=1, BundleOfEnvelopes=293}
Received data: 611.673 kB; {AddDataMessage=231, NewDaoStateHashMessage=6, AddPersistableNetworkPayloadMessage=22, GetPeersResponse=1, RefreshOfferMessage=1292, RemoveDataMessage=14, NewBlockBroadcastMessage=4}
CPU time spent on sending messages: 0.424 seconds
CPU time spent on receiving messages: 2.611 seconds
 
Dec-23 17:38:53.216 [JavaFX Application Thread] INFO  b.n.p2p.network.Statistic: Accumulated network statistics:
Bytes sent: 40.519 MB;
Number of sent messages/Sent messages: 22260 / {PreliminaryGetDataRequest=2, NewDaoStateHashMessage=51, GetBlocksRequest=1, GetProposalStateHashesRequest=2, RefreshOfferMessage=4363, RemoveDataMessage=143, GetPeersRequest=12, BundleOfEnvelopes=16509, AddDataMessage=814, GetDaoStateHashesRequest=2, GetBlindVoteStateHashesRequest=2, AddPersistableNetworkPayloadMessage=291, GetPeersResponse=13, Ping=1, NewBlockBroadcastMessage=36, GetUpdatedDataRequest=2, RemoveMailboxDataMessage=15, Pong=1};
Number of sent messages per sec: 1.5458333333333334;
Bytes received: 36.465 MB
Number of received messages/Received messages: 19804 / {NewDaoStateHashMessage=39, GetProposalStateHashesResponse=2, RefreshOfferMessage=3837, RemoveDataMessage=119, GetPeersRequest=13, GetBlindVoteStateHashesResponse=2, BundleOfEnvelopes=14734, AddDataMessage=729, GetDaoStateHashesResponse=2, AddPersistableNetworkPayloadMessage=252, GetPeersResponse=12, Ping=1, GetDataResponse=4, NewBlockBroadcastMessage=32, CloseConnectionMessage=11, RemoveMailboxDataMessage=13, GetBlocksResponse=1, Pong=1};
Number of received messages per sec: 1.3752777777777778;
Number of threads: 77

[chimp1984]

To increase the logging frequency of number of threads to 60 min would defeat the intention to learn about potential issues in cases of lost messages/network issues. It will be less likely that the log would fall close to the period when the issue happens. Maybe we can use a separate periodic log for the number of threads with a rather short period (at least less than 15 min, better shorter).

[chimp1984]

utACK

[ghost]

Maybe we can use a separate periodic log for the number of threads with a rather short period

Just noticed we're already logging the thread count every 10 minutes:

bisq/common/src/main/java/bisq/common/util/Profiler.java

Line 38 in 963b966

log.info("Total memory: {}; Used memory: {}; Free memory: {}; Max memory: {}; No. of threads: {}",

example

bisq_9.log:Nov-26 09:08:09.023 [main] INFO  b.c.u.Profiler: Total memory: 128 MB; Used memory: 35.964 MB; Free memory: 92.036 MB; Max memory: 2 GB; No. of threads: 1 
bisq_9.log:Nov-26 09:18:09.727 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 577 MB; Used memory: 542.871 MB; Free memory: 34.129 MB; Max memory: 2 GB; No. of threads: 74 
bisq_9.log:Nov-26 09:28:09.723 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 637 MB; Used memory: 589.277 MB; Free memory: 47.723 MB; Max memory: 2 GB; No. of threads: 72 
bisq_9.log:Nov-26 09:38:09.726 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 672 MB; Used memory: 625.756 MB; Free memory: 46.244 MB; Max memory: 2 GB; No. of threads: 72 
bisq_9.log:Nov-26 09:48:09.730 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 691 MB; Used memory: 632.724 MB; Free memory: 58.276 MB; Max memory: 2 GB; No. of threads: 72 
bisq_9.log:Nov-26 09:58:09.726 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 721 MB; Used memory: 679.546 MB; Free memory: 41.454 MB; Max memory: 2 GB; No. of threads: 72 
bisq_9.log:Nov-26 10:08:09.721 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 736 MB; Used memory: 622.522 MB; Free memory: 113.478 MB; Max memory: 2 GB; No. of threads: 76 
bisq_9.log:Nov-26 10:18:09.719 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 736 MB; Used memory: 642.334 MB; Free memory: 93.666 MB; Max memory: 2 GB; No. of threads: 74 
bisq_9.log:Nov-26 10:28:09.726 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 736 MB; Used memory: 616.273 MB; Free memory: 119.727 MB; Max memory: 2 GB; No. of threads: 72 
bisq_9.log:Nov-26 10:38:09.726 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 736 MB; Used memory: 624.33 MB; Free memory: 111.67 MB; Max memory: 2 GB; No. of threads: 72 
bisq_9.log:Nov-26 10:48:09.719 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 736 MB; Used memory: 653.407 MB; Free memory: 82.593 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 10:58:09.732 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 751 MB; Used memory: 606.225 MB; Free memory: 144.775 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 11:08:09.727 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 751 MB; Used memory: 624.231 MB; Free memory: 126.769 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 11:18:09.733 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 628 MB; Used memory: 584.784 MB; Free memory: 43.216 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 11:28:09.726 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 677 MB; Used memory: 646.294 MB; Free memory: 30.706 MB; Max memory: 2 GB; No. of threads: 66 
bisq_9.log:Nov-26 11:38:09.733 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 629 MB; Used memory: 580.585 MB; Free memory: 48.415 MB; Max memory: 2 GB; No. of threads: 70 
bisq_9.log:Nov-26 11:48:09.729 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 686 MB; Used memory: 602.936 MB; Free memory: 83.064 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 11:58:09.721 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 740 MB; Used memory: 690.403 MB; Free memory: 49.597 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 12:08:09.758 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 708 MB; Used memory: 631.827 MB; Free memory: 76.173 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 12:18:09.729 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 708 MB; Used memory: 651.782 MB; Free memory: 56.218 MB; Max memory: 2 GB; No. of threads: 68 
bisq_9.log:Nov-26 12:28:09.734 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 723 MB; Used memory: 667.927 MB; Free memory: 55.073 MB; Max memory: 2 GB; No. of threads: 72 
bisq_9.log:Nov-26 12:38:09.732 [JavaFX Application Thread] INFO  b.c.u.Profiler: Total memory: 1.229 GB; Used memory: 724.583 MB; Free memory: 533.417 MB; Max memory: 2 GB; No. of threads: 67 

[chimp1984]

utACK

[ripcurlx]

utACK based on #5935 (review)