mimblewimble / grin

Minimal implementation of the Mimblewimble protocol.
https://grin.mw/
Apache License 2.0
5.04k stars 991 forks source link

header sync (small numbers of headers from a single peer) #1590

Closed antiochp closed 6 years ago

antiochp commented 6 years ago

This is on a clean node with a reasonable number of healthy peers.

1) Why are we only receiving 8 headers at a time (and not ~500)? 2) Why are we only receiving them from a single peer?

Sep 26 17:34:00.098 DEBG monitor_peers: on 0.0.0.0:13414, 13 connected (9 most_work). all 147 = 113 healthy + 0 banned + 34 defunct
Sep 26 17:34:20.174 DEBG monitor_peers: on 0.0.0.0:13414, 13 connected (9 most_work). all 147 = 113 healthy + 0 banned + 34 defunct
Sep 26 17:34:40.255 DEBG monitor_peers: on 0.0.0.0:13414, 13 connected (9 most_work). all 147 = 113 healthy + 0 banned + 34 defunct
Sep 26 17:35:00.316 DEBG monitor_peers: on 0.0.0.0:13414, 13 connected (9 most_work). all 147 = 113 healthy + 0 banned + 34 defunct
Sep 26 17:32:25.396 INFO Received block headers [01008955, 02073525, 0ddf9704, 0c59a26a, 048ac66f, 044cccab, 0970b9e5, 00753f1f] from 51.15.219.12:13414
Sep 26 17:32:25.405 INFO Received block headers [06580037, 0756a564, 0d78757a, 032b0659, 0e8705ab, 0ef68dfb, 008f3b6d, 08524964] from 51.15.219.12:13414
Sep 26 17:32:25.414 INFO Received block headers [09cf6bc7, 02cc275e, 0e719548, 0120c8eb, 01f0bbf4, 0e8b9107, 09e7c3ec, 0d36a99a] from 51.15.219.12:13414
Sep 26 17:32:25.421 INFO Received block headers [0fc40b20, 0b8ca7b5, 0328e70a, 11e4aec4, 00d3074b, 107a2454, 0e5570fe, 0a082801] from 51.15.219.12:13414
Sep 26 17:32:25.428 INFO Received block headers [06be4123, 0e7a1b99, 0f12d562, 116735a3, 0ec45625, 077b4026, 0b1e39a3, 0d6b6d35] from 51.15.219.12:13414
Sep 26 17:32:25.436 INFO Received block headers [03dbec77, 0797007d, 03e54702, 10bfe6b1, 017e6900, 0c08141f, 1201efa7, 07585cc0] from 51.15.219.12:13414
Sep 26 17:32:25.445 INFO Received block headers [0789d465, 01bd455e, 13a7cc17, 05488630, 1177e53d, 07e7bcd0, 04df2dc4, 099874a3] from 51.15.219.12:13414
Sep 26 17:32:25.453 INFO Received block headers [0bd96a6c, 087196d1, 0090cf30, 02592f20, 0ae69637, 0b2cccb6, 0369a61b, 072e08b4] from 51.15.219.12:13414
Sep 26 17:32:25.461 INFO Received block headers [084b64c0, 047bbbb2, 0dcf7dd6, 169c6322, 10b91886, 05da214c, 02345f30, 0bbbb73d] from 51.15.219.12:13414
Sep 26 17:32:25.469 INFO Received block headers [14437df9, 1247c9d9, 110117fb, 0ca3cb74, 09d718e2, 03be4225, 02cfbb0a, 1712451a] from 51.15.219.12:13414
Sep 26 17:32:25.476 INFO Received block headers [04f9c481, 11666abd, 133d47cc, 026a2515, 045d6b5e, 04aaa70d, 023396f7, 0e8a4252] from 51.15.219.12:13414
Sep 26 17:32:25.484 INFO Received block headers [13d7a968, 06b8eea6, 0c1fc388, 035251bc, 094139cf, 13a0bdb8, 060bc97d, 0f9afd6c] from 51.15.219.12:13414
Sep 26 17:32:25.491 INFO Received block headers [10152866, 125bc715, 1666b1bd, 090aaa87, 05f48bf6, 0564e8b0, 0347ade6, 0f2360a8] from 51.15.219.12:13414
Sep 26 17:32:25.500 INFO Received block headers [11468091, 0cd6ec2f, 0e24ca3f, 06fe9278, 0d542211, 01b500be, 0bbeda30, 065c072a] from 51.15.219.12:13414
Sep 26 17:32:25.508 INFO Received block headers [0a579b2e, 0f6d0ce9, 0632d5ff, 07e3bf21, 09eb4da8, 071327e2, 0bd15ffa, 148dfd3b] from 51.15.219.12:13414
Sep 26 17:32:25.515 INFO Received block headers [150cacc0, 144c8e11, 151115c6, 0e8199b6, 02c63502, 0d4a5265, 0e960eb1, 0e404853] from 51.15.219.12:13414
Sep 26 17:32:25.522 INFO Received block headers [0e27b140, 144ffc7c, 07b9d4aa, 0db04289, 01bfec84, 113c49df, 0dbd680c, 0cf42a78] from 51.15.219.12:13414
Sep 26 17:32:25.530 INFO Received block headers [14fccd0b, 09d278ff, 02bda326, 0ae0d4df, 06c479ef, 0644f3b0, 178134c8, 0757bf54] from 51.15.219.12:13414
Sep 26 17:32:25.536 INFO Received block headers [1bf04d5c, 12960e6d, 1dbc055e, 06e2696b, 0e132afc, 160c8374, 150f966a, 0bf111d6] from 51.15.219.12:13414
Sep 26 17:32:25.543 INFO Received block headers [1345cf0b, 0f07a2aa, 0192930b, 0f14d11d, 0d2ec5d0, 14ee8f72, 148565eb, 07e4945b] from 51.15.219.12:13414
Sep 26 17:32:25.553 INFO Received block headers [0c206208, 1d8b8305, 1f3ae1bb, 1b911dc5, 025096f0, 01500a87, 00caae22, 00ddd3cb] from 51.15.219.12:13414
Sep 26 17:32:25.571 INFO Received block headers [039f5c40, 0d4cc8f7, 15f28134, 087251dd, 25ca8f20, 1f6e6eb5, 0bfb3b1f, 28d547f3] from 51.15.219.12:13414
Sep 26 17:32:25.581 INFO Received block headers [04892686, 1ce4fce6, 27ba3c7d, 0423aa74, 0c8e6670, 1bb14b0e, 26f58f77, 020745a8] from 51.15.219.12:13414
Sep 26 17:32:25.587 INFO Received block headers [061f8229, 25bdf9ca, 03990a47, 0c5a5168, 188c3cfa, 15ad8785, 1a132588, 281c8008] from 51.15.219.12:13414
Sep 26 17:32:25.595 INFO Received block headers [1e1861dc, 05131197, 124e6a7d, 16c3f5ff, 220ba0cf, 26eb0af0, 2c4b9996, 165a7987] from 51.15.219.12:13414
Sep 26 17:32:25.602 INFO Received block headers [2d32ad91, 29e57caa, 2b624bd6, 1770589a, 1b192246, 2a6f7e03, 1c323245, 11f376bb] from 51.15.219.12:13414
Sep 26 17:32:25.610 INFO Received block headers [22fb5821, 12642419, 2b337ad1, 05572d7c, 32c01a82, 26583ef5, 22248916, 08c0cd5c] from 51.15.219.12:13414
Sep 26 17:32:25.618 INFO Received block headers [056dbf29, 2b61d81d, 2aec57b1, 2f319018, 2475c6d4, 0ed89570, 1c7b4cf2, 2301fe81] from 51.15.219.12:13414
Sep 26 17:32:25.625 INFO Received block headers [1e8034af, 103d1ae6, 24db04fd, 1a087f66, 30b0fe85, 087e567d, 1873baf6, 2c7ce9ce] from 51.15.219.12:13414
Sep 26 17:32:25.632 INFO Received block headers [2b948102, 18c0c69b, 32dd48a0, 1eeba8fc, 1a775f33, 112f6252, 21911de7, 15b2f03e] from 51.15.219.12:13414
Sep 26 17:32:25.639 INFO Received block headers [280997e6, 194d5e4f, 1576579b, 33292b52, 26a311ff, 21d98927, 0f000d95, 31bc09dd] from 51.15.219.12:13414
Sep 26 17:32:25.646 INFO Received block headers [2ccaa0c7, 0871e566, 1986359f, 1968e9a9, 0be2b1fd, 0b716b37, 1e3d116d, 299f1c1e] from 51.15.219.12:13414
Sep 26 17:32:25.653 INFO Received block headers [1ba23bf3, 1d0da53b, 35e3bf1a, 3ad32db6, 3865750d, 34c86e80, 24269ad7, 3d957a80] from 51.15.219.12:13414
Sep 26 17:32:25.661 INFO Received block headers [386de623, 078cf61c, 1db0c7a3, 10fb0592, 12a171bd, 2f8f14b0, 3aa08764, 0dce18de] from 51.15.219.12:13414
Sep 26 17:32:25.670 INFO Received block headers [0283d4db, 044f0378, 0443f3b5, 394e70ef, 3168cf3d, 2ab7bffb, 37f2b175, 3ed08a0e] from 51.15.219.12:13414
Sep 26 17:32:25.678 INFO Received block headers [2d3ed9f9, 197ccd64, 24955d93, 2a6a6a0d, 1bd0679c, 28daa24f, 0f776e8d, 0af2ed49] from 51.15.219.12:13414
Sep 26 17:32:25.685 INFO Received block headers [0fc0031e, 15ea04ff, 1f144833, 32d41d17, 029740d7, 2beed008, 1c115072, 1faa4a40] from 51.15.219.12:13414
Sep 26 17:32:25.692 INFO Received block headers [265f192f, 05e67851, 25ac7ad7, 12fbf259, 2c2463a2, 19c18397, 045bb742, 333869d7] from 51.15.219.12:13414
Sep 26 17:32:25.699 INFO Received block headers [2d6df3ce, 1a39bac9, 3a8808a3, 3f6c1406, 05cf518a, 0e25d13b, 3443cbde, 19b63350] from 51.15.219.12:13414
Sep 26 17:32:25.706 INFO Received block headers [11466694, 30bd755a, 1946b64e, 306326c6, 1eca5452, 23d913b7, 3586cc8d, 0d88f2b9] from 51.15.219.12:13414
Sep 26 17:32:25.713 INFO Received block headers [2133fc1a, 1c5c85db, 24055d63, 28a17891, 03d5815d, 0f56a8f6, 3ef02510, 17184ea5] from 51.15.219.12:13414
Sep 26 17:32:25.721 INFO Received block headers [19e3657e, 3bc75d4b, 2f52e38d, 07d0d9ab, 089dc1ee, 131fbd8b, 0cc47e3b, 275a51db] from 51.15.219.12:13414
Sep 26 17:32:25.729 INFO Received block headers [15619924, 17d772f1, 0ea372f2, 119243e7, 2d543b96, 2e01f3fc, 247e9bc6, 0e9bb29c] from 51.15.219.12:13414
Sep 26 17:32:25.736 INFO Received block headers [1fe5af78, 2316d503, 1a17084a, 2977d3d4, 3039142d, 14e5c621, 20cd9d85, 18c6bac1] from 51.15.219.12:13414
antiochp commented 6 years ago

Is this a single message of 500 headers broken out into smaller chunks? How?

garyyu commented 6 years ago

@antiochp that is for HeaderSync optimization from https://github.com/mimblewimble/grin/pull/1400

It's not a bug 😃 The requested and received Headers from a single peer is still 511, not changed.

antiochp commented 6 years ago

It's cool. How exactly is this working? Are we effectively streaming smaller chunks of headers into the processing pipeline from the adapter?

garyyu commented 6 years ago

Thanks @antiochp And Yes, exactly.

BTW, I was planing to do a similar optimization for full sync, the basic idea is using two threads, one is ONLY for downloading, another one is ONLY for processing. and the processing worker thread will accumulate enough blocks to do one time (for better aggregation processing).

But I'm not sure what you will do in https://github.com/mimblewimble/grin/issues/1470, so I suspend the plan.

antiochp commented 6 years ago

Can you point me at the code where we break this into batches of 8 headers? Looking at how/where to wire in the header mmr processing. This involves starting a relatively expensive txhashset (or similar) extension, and would benefit from a larger batch size so we could apply many headers at once.

garyyu commented 6 years ago

@antiochp

Can you point me at the code where we break this into batches of 8 headers?

https://github.com/mimblewimble/grin/blob/master/p2p/src/protocol.rs#L187

antiochp commented 6 years ago

OK - one more question... 😄

If we have 511 headers in a full Headers msg, this breaks out into multiple batches of 8 headers followed by a batch of 7 headers. But what we actually see is a batch of 6 followed by a batch of 1 header.

Why 8,8,8,6,1,8,8,8,6,1 and not 8,8,8,7,8,8,8,7?

...
Sep 28 15:07:35.216 DEBG pipe: sync_block_headers: 8 headers from 02c3d340 at 94478
Sep 28 15:07:35.225 DEBG pipe: sync_block_headers: 8 headers from 06023fca at 94486
Sep 28 15:07:35.234 DEBG pipe: sync_block_headers: 8 headers from 027e667c at 94494
Sep 28 15:07:35.242 DEBG pipe: sync_block_headers: 6 headers from 0899e5ee at 94502
Sep 28 15:07:35.249 DEBG pipe: sync_block_headers: 1 headers from 09fdfe78 at 94508
Sep 28 15:07:35.337 DEBG pipe: sync_block_headers: 8 headers from 089d6a0c at 94509
Sep 28 15:07:35.348 DEBG pipe: sync_block_headers: 8 headers from 02e7b9bc at 94517
Sep 28 15:07:35.356 DEBG pipe: sync_block_headers: 8 headers from 02b859f3 at 94525
...
Sep 28 15:07:35.869 DEBG pipe: sync_block_headers: 8 headers from 03b6687e at 94989
Sep 28 15:07:35.878 DEBG pipe: sync_block_headers: 8 headers from 0a7be34d at 94997
Sep 28 15:07:35.887 DEBG pipe: sync_block_headers: 8 headers from 04d83a7c at 95005
Sep 28 15:07:35.896 DEBG pipe: sync_block_headers: 6 headers from 0943214d at 95013
Sep 28 15:07:35.903 DEBG pipe: sync_block_headers: 1 headers from 089763d9 at 95019
Sep 28 15:07:36.050 DEBG pipe: sync_block_headers: 8 headers from 044e85ee at 95020
Sep 28 15:07:36.061 DEBG pipe: sync_block_headers: 8 headers from 07b5af0e at 95028
Sep 28 15:07:36.069 DEBG pipe: sync_block_headers: 8 headers from 019497f6 at 95036
Sep 28 15:07:36.076 DEBG pipe: sync_block_headers: 8 headers from 0a704156 at 95044
...
garyyu commented 6 years ago

You find one of my remaining issues! 😄 otherwise this splitting is perfect. It's a little bit complex. I know root cause of this, but so far no plan to fix this. Let me try to explain the root cause:

  1. Header length is variable, for different cuckoo size. One Headers package could contain Header with different size
  2. We don't have easy way to split the Headers (because of no Header length field which I had argued before but reject by Igno), only way is to deserialization these Headers
  3. To avoid deserialization error (which will trigger error handling and make all the remaining Headers fail), we have to give exact size of whole Headers, or giving more data, and MUST NOT less.
  4. So, for compatibility with variable size of block header, we read max possible size (i.e. max_header_size), for up to Cuckoo 36.
  5. When only 7 Headers remaining, we read all data into buffer for deserialization.
  6. But we need set the exact size of this header vector before calling deserialize, the difficult part is before deserialization we indeed don't know the exact size! So we have to estimate it:

https://github.com/mimblewimble/grin/blob/master/p2p/src/protocol.rs#L368-L372

    let mut final_headers_num = (read_size + reserved.len() as u64) / max_header_size;
    let remaining = msg_len - *total_read - read_size;
    if final_headers_num == 0 && remaining == 0 {
        final_headers_num = 1;
    }

look at above 4 lines of code, that's why we always have 1 Header left for the final call.

antiochp commented 6 years ago

Closing. Related #1627.