Blooms recomputation in case of a fork is very slow

[usd-yamazaki]

I'm running:

• Which Parity version?: Parity/v1.9.5-stable-ff821da-20180321/x86_64-linux-gnu/rustc1.24.1
• Which operating system?: Ubuntu 16.04.2 LTS
• How installed?: via installer
• Are you fully synchronized?: yes
• Which network are you connected to?: private PoA (Aura)
• Did you try to restart the node?: yes

Node list

• AU1: Sealing node
• AU2: Sealing node
• OB1: eth_sendRawTransaction execution node (not seal)
• OB2: ordinary node (not seal)

I am sending externally created transactions to private PoA chain with eth_sendRawTransaction.
Send 6400 transactions from one account at a time and wait for synchronization.
Each transaction uses 1649 bytes and uses approximately 1.15 M gas.
If a temporary fork occurs during this sync, subsequent synchronization will be extremely slow.
In normal case, it takes about 7 minutes for all transactions to be processed.
If a temporary fork occurs, it takes about 30 minutes for all transactions to be processed.
During this time, the CPU usage rate will be 100%, but memory and storage are calm.

In this log, a temporary fork occurs between AU1 and AU2 at #1638747, and long time synchronization of OB1 starts at that timing.
At this time, there were about 3700 pending transactions for OB1.

AU1

2018-05-02 20:17:20  Imported #1638744 fa14…7c6e (2 txs, 2.37 Mgas, 100.78 ms, 3.79 KiB)
2018-05-02 20:17:26  Imported #1638745 9e7e…bdc9 (304 txs, 352.14 Mgas, 584.05 ms, 489.75 KiB)
2018-05-02 20:17:30  Imported #1638746 54d2…aa53 (0 txs, 0.00 Mgas, 4.88 ms, 0.57 KiB)
2018-05-02 20:17:42  Imported #1638747 6f11…18b0 (5 txs, 5.79 Mgas, 2354.12 ms, 8.63 KiB)
2018-05-02 20:17:45  Imported #1638748 aeaf…5edd (3 txs, 3.48 Mgas, 9.47 ms, 5.41 KiB) + another 1 block(s) containing 1170 tx(s)
2018-05-02 20:17:50  Imported #1638749 08b1…b7d0 (0 txs, 0.00 Mgas, 4.80 ms, 0.57 KiB)
2018-05-02 20:17:54     3/25 peers   5 MiB chain 126 MiB db 0 bytes queue 17 KiB sync  RPC:  0 conn,  0 req/s,  87 µs
2018-05-02 20:17:55  Imported #1638750 a921…0c31 (0 txs, 0.00 Mgas, 0.52 ms, 0.57 KiB)
2018-05-02 20:18:00  Imported #1638751 c06e…7b07 (0 txs, 0.00 Mgas, 6.53 ms, 0.57 KiB)
2018-05-02 20:18:13  Imported #1638752 5b27…2b25 (1168 txs, 1352.97 Mgas, 608.62 ms, 1881.46 KiB)

AU2

2018-05-02 20:17:15  Imported #1638743 bf52…367a (0 txs, 0.00 Mgas, 1.92 ms, 0.57 KiB)
2018-05-02 20:17:20  Imported #1638744 fa14…7c6e (2 txs, 2.37 Mgas, 3.90 ms, 3.79 KiB)
2018-05-02 20:17:25  Imported #1638745 9e7e…bdc9 (304 txs, 352.14 Mgas, 75.24 ms, 489.75 KiB)
2018-05-02 20:17:30  Imported #1638746 54d2…aa53 (0 txs, 0.00 Mgas, 0.53 ms, 0.57 KiB)
2018-05-02 20:17:39  Imported #1638747 1798…0cbd (1170 txs, 1355.29 Mgas, 282.82 ms, 1884.68 KiB)
2018-05-02 20:17:40     3/25 peers   3 MiB chain 19 KiB db 0 bytes queue 17 KiB sync  RPC:  0 conn,  0 req/s,  70 µs
2018-05-02 20:17:45  Imported #1638748 aeaf…5edd (3 txs, 3.48 Mgas, 25.79 ms, 5.41 KiB)
2018-05-02 20:17:50  Imported #1638747 6f11…18b0 (5 txs, 5.79 Mgas, 17.19 ms, 8.63 KiB)
2018-05-02 20:17:55  Imported #1638750 a921…0c31 (0 txs, 0.00 Mgas, 3.88 ms, 0.57 KiB) + another 1 block(s) containing 0 tx(s)
2018-05-02 20:18:00  Imported #1638751 c06e…7b07 (0 txs, 0.00 Mgas, 0.54 ms, 0.57 KiB)
2018-05-02 20:18:09  Imported #1638752 9f3c…1f24 (1168 txs, 1352.97 Mgas, 313.54 ms, 1881.46 KiB)

OB1

2018-05-02 20:17:15  Imported #1638743 bf52…367a (0 txs, 0.00 Mgas, 0.60 ms, 0.57 KiB)
2018-05-02 20:17:20  Transaction mined (hash 6dc721cc68969d0befe0fdb9999ddcdd3d1056fa2fe59a069633e489aa741d89)
2018-05-02 20:17:20  Transaction mined (hash 89f58c78c61b4c8a521fb44bb1d7df24ecac50d673b3142834ebc65c376516ea)
2018-05-02 20:17:20  Imported #1638744 fa14…7c6e (2 txs, 2.37 Mgas, 5.38 ms, 3.79 KiB)
2018-05-02 20:17:26  Transaction mined (hash e8efb8517068d8e7994259eafd4f0380d71a84d23f1628920f81174a80cb7774)
(303 same rows)
2018-05-02 20:17:29  Imported #1638745 9e7e…bdc9 (304 txs, 352.14 Mgas, 782.08 ms, 489.75 KiB)
2018-05-02 20:17:31     3/25 peers   793 KiB chain 142 MiB db 0 bytes queue 41 KiB sync  RPC:  1 conn, 176 req/s, 852 µs
2018-05-02 20:17:35  Imported #1638746 54d2…aa53 (0 txs, 0.00 Mgas, 0.59 ms, 0.57 KiB)
2018-05-02 20:17:45  Transaction mined (hash 8e8cdab7eff75b09dd8501db71aae26fbc61451794b89a5b9b1c1b8987dc6ed8)
(1172 same rows)
2018-05-02 20:18:06     3/25 peers   9 MiB chain 141 MiB db 3 KiB queue 41 KiB sync  RPC:  1 conn, 86 req/s, 1712 µs
2018-05-02 20:18:16  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s      4+    0 Qed  #1638753    3/25 peers   9 MiB chain 141 MiB db 2 MiB queue 41 KiB sync  RPC:  1 conn, 76 req/s, 1688 µs
2018-05-02 20:18:26  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s      7+    0 Qed  #1638755    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 76 req/s, 1682 µs
2018-05-02 20:18:36  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s      9+    0 Qed  #1638757    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 50 req/s, 1670 µs
2018-05-02 20:18:46  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     11+    0 Qed  #1638759    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 50 req/s, 1468 µs
2018-05-02 20:18:56  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     13+    0 Qed  #1638761    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 51 req/s,  60 µs
2018-05-02 20:19:06  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     15+    0 Qed  #1638763    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 51 req/s,  57 µs
2018-05-02 20:19:16  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     17+    0 Qed  #1638765    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 51 req/s,  56 µs
2018-05-02 20:19:26  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     19+    0 Qed  #1638767    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 52 req/s,  55 µs
2018-05-02 20:19:36  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     21+    0 Qed  #1638769    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 52 req/s,  55 µs
2018-05-02 20:19:46  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     23+    0 Qed  #1638771    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 62 req/s,  55 µs
2018-05-02 20:19:56  Syncing #1638749 08b1…b7d0     0 blk/s    0 tx/s   0 Mgas/s     25+    0 Qed  #1638773    3/25 peers   9 MiB chain 141 MiB db 6 MiB queue 41 KiB sync  RPC:  1 conn, 62 req/s,  54 µs

(about 30 minutes)

2018-05-02 20:47:50  Imported #1639097 9651…82d9 (0 txs, 0.00 Mgas, 0.75 ms, 0.57 KiB) + another 13 block(s) containing 3 tx(s)
2018-05-02 20:48:11  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s      4+    0 Qed  #1639105    3/25 peers   30 MiB chain 143 MiB db 6 KiB queue 41 KiB sync  RPC:  1 conn,  8 req/s,  53 µs
2018-05-02 20:48:21  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s      6+    0 Qed  #1639107    3/25 peers   30 MiB chain 143 MiB db 9 KiB queue 41 KiB sync  RPC:  1 conn,  2 req/s,  52 µs
2018-05-02 20:48:31  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s      8+    0 Qed  #1639109    3/25 peers   30 MiB chain 143 MiB db 12 KiB queue 41 KiB sync  RPC:  1 conn,  1 req/s,  52 µs
2018-05-02 20:48:41  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s     10+    0 Qed  #1639111    3/25 peers   30 MiB chain 143 MiB db 15 KiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  50 µs
2018-05-02 20:48:51  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s     12+    0 Qed  #1639113    3/25 peers   30 MiB chain 143 MiB db 18 KiB queue 41 KiB sync  RPC:  1 conn,  1 req/s,  50 µs
2018-05-02 20:49:01  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s     14+    0 Qed  #1639115    3/25 peers   30 MiB chain 143 MiB db 22 KiB queue 41 KiB sync  RPC:  1 conn,  2 req/s,  50 µs
2018-05-02 20:49:11  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s     16+    0 Qed  #1639117    3/25 peers   30 MiB chain 143 MiB db 25 KiB queue 41 KiB sync  RPC:  1 conn,  1 req/s,  49 µs
2018-05-02 20:49:21  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s     18+    0 Qed  #1639119    3/25 peers   30 MiB chain 143 MiB db 28 KiB queue 41 KiB sync  RPC:  1 conn,  1 req/s,  49 µs
2018-05-02 20:49:31  Syncing #1639101 b6b1…fc76     0 blk/s    0 tx/s   0 Mgas/s     20+    0 Qed  #1639121    3/25 peers   30 MiB chain 143 MiB db 31 KiB queue 41 KiB sync  RPC:  1 conn,  1 req/s,  49 µs
2018-05-02 20:49:37  Imported #1639101 b6b1…fc76 (0 txs, 0.00 Mgas, 0.73 ms, 0.57 KiB) + another 1 block(s) containing 0 tx(s)
2018-05-02 20:50:01     3/25 peers   30 MiB chain 143 MiB db 2 KiB queue 41 KiB sync  RPC:  1 conn,  2 req/s,  49 µs
2018-05-02 20:50:16  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s      5+    0 Qed  #1639127    3/25 peers   30 MiB chain 143 MiB db 2 MiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  49 µs
2018-05-02 20:50:26  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s      6+    0 Qed  #1639128    3/25 peers   30 MiB chain 143 MiB db 2 MiB queue 41 KiB sync  RPC:  1 conn,  4 req/s,  49 µs
2018-05-02 20:50:36  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s      9+    0 Qed  #1639130    3/25 peers   30 MiB chain 143 MiB db 4 MiB queue 41 KiB sync  RPC:  1 conn,  1 req/s,  49 µs
2018-05-02 20:50:46  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s     11+    0 Qed  #1639132    3/25 peers   30 MiB chain 143 MiB db 4 MiB queue 41 KiB sync  RPC:  1 conn,  2 req/s,  49 µs
2018-05-02 20:50:56  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s     13+    0 Qed  #1639134    3/25 peers   30 MiB chain 143 MiB db 4 MiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  49 µs
2018-05-02 20:51:06  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s     15+    0 Qed  #1639136    3/25 peers   30 MiB chain 143 MiB db 4 MiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  49 µs
2018-05-02 20:51:16  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s     17+    0 Qed  #1639138    3/25 peers   30 MiB chain 143 MiB db 4 MiB queue 41 KiB sync  RPC:  1 conn,  2 req/s,  49 µs
2018-05-02 20:51:26  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s     19+    0 Qed  #1639140    3/25 peers   30 MiB chain 143 MiB db 4 MiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  49 µs
2018-05-02 20:51:36  Syncing #1639122 866c…2e61     0 blk/s    0 tx/s   0 Mgas/s     21+    0 Qed  #1639142    3/25 peers   30 MiB chain 143 MiB db 4 MiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  47 µs
2018-05-02 20:51:46  Syncing #1639123 9a7b…df0c     0 blk/s    0 tx/s   0 Mgas/s     21+    0 Qed  #1639144    3/25 peers   30 MiB chain 143 MiB db 2 MiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  47 µs
2018-05-02 20:51:56  Syncing #1639123 9a7b…df0c     0 blk/s    0 tx/s   0 Mgas/s     23+    0 Qed  #1639146    3/25 peers   30 MiB chain 143 MiB db 2 MiB queue 41 KiB sync  RPC:  1 conn,  3 req/s,  47 µs
2018-05-02 20:52:04  Transaction mined (hash 33fc95d0270882b3b9ec0fb72c1ad7798bf91f9e4a004e898e6cd8b9973d46ea)
(1169 same rows)
2018-05-02 20:52:05  Imported #1639147 7bad…61e0 (0 txs, 0.00 Mgas, 0.37 ms, 0.57 KiB) + another 1 block(s) containing 0 tx(s)
2018-05-02 20:52:06  Imported #1639148 39b5…5ce3 (0 txs, 0.00 Mgas, 0.53 ms, 0.57 KiB)
2018-05-02 20:52:12  Transaction mined (hash 0d71da1250c9eb9739175462364faf7bc53198975f52876154fbdcca11d78128)
(1169 same rows)
2018-05-02 20:52:12  Imported #1639149 3a6e…1dc2 (1170 txs, 130.22 Mgas, 993.14 ms, 1884.68 KiB)
2018-05-02 20:52:15  Transaction mined (hash 955d8b6bccf8a1057b324eb04551c65c1068d46cac3b301462179674c6d79deb)
(109 same rows)
2018-05-02 20:52:15  Imported #1639150 dd37…dda4 (110 txs, 12.24 Mgas, 130.00 ms, 177.71 KiB)
2018-05-02 20:52:16  Imported #1639121 6081…2350 (0 txs, 0.00 Mgas, 0.38 ms, 0.57 KiB)
2018-05-02 20:52:20  Imported #1639151 1691…7e4f (0 txs, 0.00 Mgas, 0.74 ms, 0.57 KiB)
2018-05-02 20:52:25  Imported #1639152 4246…6cbc (0 txs, 0.00 Mgas, 0.78 ms, 0.57 KiB)

[tomusdrw]

Might have something to do either with bloom re-orgs or transaction re-importing. The latter should be fixed with the new transaction pool implementation present in 1.11.
Do the transactions produce many log statements/emit many events?

[usd-yamazaki]

Since 20 events are created per transaction, a total of 128,000 events are created.
Does event creation slow down synchronization?

[tomusdrw]

@usd-yamazaki Indeed it might be an issue, Parity is maintaining a tree of event bloom filters (mipmap) to allow efficient log querying.
In case of the re-org the bloom filters need to be recomputed, most likely that's suboptimal, since the forks should not happen often.

[folsen]

@debris will your new bloom work address this at all?

[debris]

yes, entirely