April 2023

Spent today tracking down a crash in tx.connect(...) [script validation] at block 307,574. This resulted from optimizations I made in system's elliptic curve wrapper functions. An empty data_slice buffer.data() returns a null pointer (same for std::array and std::vector). This was getting passed into libsecp256k1, resulting in an assert/abort on the null pointer. This is now guarded, as were the other calls. Yesterday I tracked down a regression in the script interpreter, where op_size() was popping vs. peeking. This resulted from my full rewrite of the stack as a variant object processor, vs. serializing all values to/from byte arrays. Neither of these were caught by the full set of bitcoind script tests, which is a strong argument for the value of actual unit testing. The script machine (program, interpreter, stack, and number classes) is now well factored for simple unit testing, but that's not done.

This is the first time the node has validated against actual live blockchain data in 3 years or so. System, database, network and node have been very significantly rewritten, almost entirely. I expect to encounter some issues. Overall still doing exceptionally well in terms of reliability.

Today tracked down a bug that invalidated block 344,511. The sigop calculation was off due to a simple math error (add vs. sub) in an chain::operations static util. Another regression from the redesigns. Marching ahead now into the territory where blocks start getting full. The database tools I have now make it significantly easier to track down these kinds of issues.

Looks like the total store less indexes is 7.4% larger than "The total size of the blockchain minus database indexes" as reported by blockchain.com. Given that we provide reverse tx indexing and constant time forward/reverse navigation for all objects, I'd say that's pretty damn efficient.

Completed full validation through block 481,823, which is the last pre-segwit block.

The sync ran up to the first segwit block at which point I ran into a few issues. I had disabled the bip9-based activation code, so I reenabled that by hacking it in. I need to go restore it fully at some point. Then I ran into a couple issues with witness commitment. First, the recent optimization to extract the witness hash from the wire serialization was flawed. This is basically math to skip around the buffer and hash the txs, for both wtxid and txid. I had to tweak the offsets txid initially (for a tx count value I missed), and this required me to tweak the offsets on the wtxid (for a similar issue). These hashes really only affect the witness commitment, so that was failing. Second, there was a simple inversion in the witness commitment extraction from the coinbase. I ended up patching this twice. Another issue was a script number bug. This only came into play in the case of segwit ("clean stack" requirement). The bool value was inverted. Also, segwit adds the constraint that the null dummy stack value in op_checkmultisig must be "false" (empty vector). The bool value was inverted. These last two were a result of the variant stack rewrite. The transaction hash optimization is new optimization code. The bip9 thing was just disabled to simplify porting and I forgot to reenable. I also ran into a disk full error, which was handled cleanly as expected by the database/node, but confused me due to the error text. This killed some time. Presently it's off and running again. I think that it's through enough segwit blocks that there isn't likely to be much more. Currently at 485422 and completing the run sequentially will take a few days.

Normally a soft work should not cause any issues if not activated, but segwit broke block/tx wire serialization, so you have to accommodate that if the node advertises segwit support.

I also spent an hour writing and testing a potential optimization in block prevout population, though it’s not clear there is a material benefit in the current context.

Topic: Dev Weekly Status Time: April 6, 2023 01:00pm Pacific Time (US and Canada) Join Zoom Meeting https://us05web.zoom.us/j/87666370902?pwd=bEZDUlJ0MGJ5V3dVMUhVdHl5QzdFdz09 Meeting ID: 876 6637 0902 Passcode: 85U0bF

Cool!

Humming along now past 500k. Had an issue with is_locked() validation, which was a result of non-populating prevout metadata. That prompted me to work off some code debt, organizing the validation functions a little more. This is because validation is split between database-optimized functions for confirmation, and check/accept/connect functions on the chain objects. Previously, and traditionally, confirmability is mixed in with validation. But our parallelism model performs these independently, because they are different concurrency constraints. So now we have check/accept/connect/confirm functions on the chain::header/block/transaction/input classes, where confirm is new. And we don't use the confirm function (which contains is_locked, since it depends on the confirmation height/mtp of the previous output) and instead node performs these checks in the database. To the extent there is any logic in the confirm functions, that is exposed via static methods on the chain classes.

About half synced, byte/tx count-wise, block 567,600.

With a long run underway, RAM has stabilized at 50% of hardware capacity (128/256GB) and disk I/O is 0-1% capacity (new SSD on 5yo machine). This is while reading each block off the disk, stored relationally across 7 tables (14 files). There's no network I/O except address updates.

624,230

784,761 (complete)

So validation completes, with all forks activated, across the full chain. On to the next thing.

I'm looking at total confirmation cost again. Recall confirmation is totally ordered (sequential) , while validation is partially-ordered (concurrent). So confirmation establishes minimum time.

By adding parallelism to the outer loop for obtaining confirmability state for the set of inputs in each block, overall time dropped to 6% of sequential - and begins to max out my 64 cores as blocks get full.

After adding parallelism the aspects of confirmation that can benefit from it (3 loops), there's some solid cost reduction, with CPU maxing out. But that benefit appears to be strongest when blocks aren't full and phases out as the sequential ops start to dominate. In this graph the blue opt line shows percentage of cost after parallelism, starting at no benefit with entirely empty blocks, and then getting down to about 20% of sequential cost, then working its way back up. I haven't done a pair of full runs to see total effect, but trend looks clear.

On this graph note that locked is zero, which is a result of bip68 not being active at these heights. Otherwise this would be up with the other lines. Orange (all/opt) is the total cost, with parallelism. As this is cumulative of the others (except opt), there are obviously side effects from each operation that benefit the others. This is most certainly the result of paging being the dominant cost, with part of the paging cost being shared when the queries run in proximity. Otherwise it's worth noting that no one query really dominates. set strong is a write operation and spent is optimized (necessarily) by a dedicated hash table.

Each individual operation is constant time in the byte size of the store and in count of txs. However the total time is significant just owing to the volume of inputs (2.2 billion). Basically constant time query but linear to perform a pass over the whole store (822 million txs) - since these operations cannot be made concurrent. I'll do a full run tonight, but I expect that determining confirmability for and setting confirmation state of each tx will require about 5-10 hours. That would set a floor on sync type, with or without validation. While validation can be highly parallelized, confirmation is using 100% cpu with concurrency. In other words, we would become doubly cpu bound during validation despite the concurrent nature of validation vs. confirmation.

I'm fairly confident that the bulk of the cost is paging time. Navigating the hash table deconfliction lists is basically random access and page loading of kbs of data to reach just a few bytes at a time. My PC has RAM for less than half the store. Prob worth a run on my big mac soon. The checking for confirmation is about half the cost and its indexation is the other half. Once this is indexed the query performance over the store is blazing, especially with RAM, but takes time to build the indexes. Core doesn't even build a tx hash index by default, so not much of a comparison.

Topic: Dev Weekly Status Time: April 13, 2023 01:00pm Pacific Time (US and Canada) Join Zoom Meeting https://us05web.zoom.us/j/87666370902?pwd=bEZDUlJ0MGJ5V3dVMUhVdHl5QzdFdz09 Meeting ID: 876 6637 0902 Passcode: 85U0bF

One things that becomes evident when working with billions of operations is that the slightest change can have a material impact. By just reorganizing some code in the query I got a reduction by 200k from 1660 secs to 277 sec.

8x, well worth it

Yeah, this is where a profiler would really help.

Here's a new one. I'm clearly getting a material performance benefit by having a function call in the inputs loop which does nothing but compare two integers and always returns false (at these heights). I've run it twice, same adds about 20sec (to 240 or 8%) to NOT have the call present. WTF

I've confirmed that the locked_prevout and mature_prevout queries are essentially redundant, so can be folded as it pertains to store interaction. That's very good to see, but the numbers I have been looking at are all from heights prior to that query activating. The redundancy arose from my late transfer of relative locktime (bip68) from validation to confirmation.

key_ is a std::array, sized to the search key width for a given table. So that's stack allocated and valid. link is a uint8_t* to the memory map. So the hot path tells me that half the time is spent comparing a search key to the memory mapped buffer. This is done in the hashmap conflict list iterator.

To get a quick validation of the linearity theory I caused a logical failure at over 100 iterations, which should be very rare. This hit as soon as it got in the populated blocks range.

This is a report of the number of times a hash table encounters a conflict list > 10 elements long - printed every 10k blocks:

block: 10000 in 0 secs.[622]
block: 20000 in 0 secs.[1152]
block: 30000 in 1 secs.[2863]
block: 40000 in 1 secs.[5071]
block: 50000 in 2 secs.[9443]
block: 60000 in 3 secs.[23051]
block: 70000 in 4 secs.[45320]
block: 80000 in 5 secs.[75748]
block: 90000 in 8 secs.[106010]
block: 100000 in 13 secs.[192285]
block: 110000 in 18 secs.[287135]
block: 120000 in 28 secs.[494607]
block: 130000 in 48 secs.[900702]
block: 140000 in 90 secs.[1752203]
block: 150000 in 131 secs.[2573178]
block: 160000 in 158 secs.[3264903]
block: 170000 in 188 secs.[4277819]
block: 180000 in 232 secs.[5754310]

saturation is the percentage of buckets in use?

This is the header saturation levels for the fully-populated archive hash tables.

That's a good point

Note that there appears to be an issue with the slabs.

Also, the above doesn't tell us how long the conflict chains are for those tables, right?

Well they will vary probabilistically. The mean will be 1.5.

At 77.91% the point table should see an average of 1.9 conflicts per query.

.. and yet you saw more for point table too?

The txs table should see an average of 7.54 (I saw a max of 7 after scanning 1% of the store).

After replacing DJB2 with nothing but a truncation and bucket modulo, this is the summary of actual hash table collisions against the full chain. Way good enough for now, especially given no hashing computation.

what's this do to your queries?

So updating test cases for this "no-hash" hash table function. I'll also add a template condition for using DJB2, in case where a table is built with a non-uniform keyspace.

OK, I finished the template parameterization of the hash function, and the updates to test expectations. Moving on to creating performance test simulations of confirmation using cache data so that inputs/outputs are never queried except as cache misses. This reduces the read order for confirmation to tx/block level, vs. input/tx/block (10^8/10^6 vs. 10^9/10^8/10^6).

Here's a fair comparison of the query difference between the two hash functions. The only change here is the template argument that controls the function. I have a full database of each index type. Both are started cold and since the databases are distinct, don't benefit from cache. The djb2 one is still running, so partial. But you can get the idea. The plot is just time by height. Incidentally, database read is maxed out at the same level (125mb/sec) in both cases.

Not the djb2 run is backing off on the store, at 100 mb/sec, which implies that processing the conflicts is outstripping paging, with a corresponding increase in slope:

A better way to look at perf is rate, since the accumulation and changes in block size can be really misleading. Here's a comparison of the completion rate of each hash as a function of the number of block bytes processed. I had to scale djb2 * 100 because its results were 2-3 orders of magnitude worse.

Here's the complete run and summary, 4x faster over 200k blocks - so worth one day's effort for sure.

I've concluded that the central issue I'm dealing with in terms of confirmation query performance is the structure of the input table. Since identification of spender(s) from an output point requires a reverse index which is 1:1 with inputs, the index was attached to the input table. This saves about 6GB in redundant storage (and is super elegant). However as inherently the largest table in the store by far (at 322GB) this space savings is entirely overwhelmed by the paging cost that it introduces. So I'm splitting out the spend index into a 30GB record table that indexes output point to spending tx. The tx is all that is required for the confirmation process. For another 10GB we could store the fk of the spending input as well, however there is no need to optimize this for validation/confirmation. The spender can otherwise be identified in constant time by walking the spending tx's inputs for the matching point, which in most cases is a walk of no more than two items, so prob not worth the extra space. The input table then becomes a blob table with no direct search, just like output. I concluded that the confirmation perf problem was limited to this one query and not a consequence of the query complexity in general after reducing the complex query to the single table. Should have some numbers on this today.

TLDR: the spender search table will be 9% of the byte size of current impl, which should resolve its excessive paging.

Test of the first 200k blocks shows time reduced to 6% of original.

sweet!!!!!

Yes. It will take me until tomorrow to get a measure across the full store.

The chart is for confirmation? wow!

Yeah, a small sample, but a really good initial result.

🎉

To get a proper run I'll need to resync the full store into the new tables. But I haven't yet reduced the input table - all I did was add the spend table with redundant indexing, and not use the input table for confirmation. But adding the new table and index was quick, just a couple hours including tests.

At 200 blocks what %age of your RAM is in use?

Then have to sync the full store, and then just fire up confirmation. This initial test was done using cached confirmation data (as if we have retained the blocks (or at least some metadata for each input) in memory after storing. But it was compared against the same test in the previous model, so it's a fair comparison.

memory still only around 60%

This is memory immediately before the confirmation run starts (after cached inputs accumulated) and just as it completes. Notice that disk activity is trivial during the run and memory only increases 2%. The input accumulation doesn't hit the spends table, so there's no cheating there.

Yup. That lookup table is small as you expected

I'm pretty sure this will put the mmap store in competetive territory.

Agree. This is looking promising. The real test is when memory is getting full - fingers crossed we will see similar improvements!

Memory being full isn't itself a material issue. Most memory is just a cache that rarely guts used. The reason this one table was an issue is that we had to page all the way through 350GB of it, and any other material table usage was casing major churn.

Yeah, just want to see what the VM subsystem decides to page in and out and when.

I did another bit of a simulation, which is at about 1/4 of the inputs after about .9hrs. Disk activity is still trivial. This isn’t an ideal test yet, but at least shows very reasonable projected completion time for a validation run.

The last quick and dirty test completed. I had staged it for 1/3 of the inputs. Finished up at just over an hour. The rate picked up a bit as blocks got fuller, but was extremely steady and very low disk I/O even with memory full. So I’d expect to see a full run take no more than 3 hrs. Since disk I/O is clearly not a limiting factor (was less than 1mb/sec vs 125mb/sec before), it means that other optimizations, such as replacing the stream and stream reader with a simple memcopy, would probably cut the time down even further.

Topic: Dev Weekly Status Time: April 20, 2023 01:00pm Pacific Time (US and Canada) Join Zoom Meeting https://us05web.zoom.us/j/87666370902?pwd=bEZDUlJ0MGJ5V3dVMUhVdHl5QzdFdz09 Meeting ID: 876 6637 0902 Passcode: 85U0bF

Over the past week I've split out the spend index from the input table. This is intended to reduce the amount of bytes paged in iterating all possibly-confirmed spenders of an output. The input table is 3/5 of the entire store, and the conflict lists are incorporated into the table body, as conflict lists independent of bodies would significantly increase store size. So moving this index to an independent table was expected to reduce the cost of the double spend query by not having to page over 350gb of data just for this simple query. The change of hash function (described above) from djb2 to "no-hash" was a material improvement generally, but not enough to mitigate this issue. So at this point the implementation of the spender table split from the input table is complete, I've performed a couple of full syncs, and run some queries to measure the change...

The fairly constant performance advantage of unguarded puts is expected, however the spike in guarded is informative. The dramatic cost increase coincided with disk thrashing. The first spike was caused by a coincident user logon that required memory, and the second was caused by a coincident source compilation that also required memory - at a time when the mmap was fully consuming RAM. In other words it had to page out some of the buffer.

Writing is essentially free except for flush, and flush is batch writing, so super efficient. But reading all over the store while you are writing the full store is problematic. This is what can be gleaned from the above. You don't want to force the indexes out of memory as it gets into thrashing. The disk I/O cost of the unguarded sync was basically zero. We want to periodically flush anyway, so by doing so we could presumably manage a very rapid and orderly population of the entire store on multiple threads. The above is just one peer, one thread, all sequential. But there is nothing preventing full concurrency of the population at this point. The write speed of the disk appears to be 500mb/sec, which it hits on a large file copy. So the full store can be flushed in 17 minutes. The time to read the store is bounded by the network bandwidth (not peer or single channel speed).

The store is larger than the wire serialization, due to indexing. Given a 1Gbit connection, the approximate minimal store download time is 69 minutes. With sequential flushing (worst case) that amounts to under 1.5 hours to download and flush the entire archive. With a full sync and full 256 GB of RAM the longest observed flush has been 8 minutes, so this is very consistent with the flush rate above.

So I ran a full sequential deserialization of the store (all transactions in order).

This was again, significant thrashing. This was strictly a read operation, and the thrashing started when the disk became full. The issue here, as with reading while writing (guarded writing), is that reading index information requires spanning the archive bodies of txs, tx, spend, and point - while also paging through the entire store. However, despite full indexes for the entire run (unlike with writing, as they are build during the run), the cost was constant and low with nothing cached in RAM. I stopped the run (accidentally) at tx 504,393,291, and then restarted it. Notice that the store warmed up very quickly (down from the peak) and averaged slightly higher than the earlier 2s/100k. But this rate had increased toward the end to an average of 2s/100k. So this was the cost of warming back up. In other words, merely dumping (not flushing, there are no writes) the memory buffer during this period prevented the thrashing. It's possible that it would have just worked itself out due to flushing had I not stopped it - as I've seen happen elsewhere. I'll do another run soon.

The read speed was very constant at 25mb/sec, apart from the thrashing period where it spiked. The full archive was sequentially read in 6.08 hours. At a rate of 25mb/sec this implies about 10% more data was read than exists in the archive. This is attributable to the thrashing episode but also to the full restart. Presumably with sufficient RAM a full run would be 100% of archive size. But given the restart and thrashing, 110% is excellent. Note that the full archive can be read in parallel, and given maximal transfer rate can be entirely read in 30 minutes (the archive is larger than the wire serialization due to indexing).

Here's a zoom on the new numbers...

Looking at the performance profile there are no obvious bottlenecks, which is good but also means no low hanging fruit. But the confirmation query must still read every input, which means it pages over every script and witness. It just doesn't page over them for the double spend query. That's important since that query is a multimap - it must exhaust the conflict list to find all possible matches (vs. just the first). But the confirmation queries only require sequence, point_fk, and parent_fk from the input table. I'm going to run some number to see what sizes would be if these were moved into the spend table and the input table was just the script and witness. This would require an extra link per input, to be stored in the spend table. Apart from the extra space, the downside is that it requires traversal of the spend table (direct, no search) in order to deserialize (read) the input/tx. Writing the data is really not a consequential difference, as both records need to be written and this just shifts from one to the other. Adding the additional link is immaterial at that point. So I'll measure the difference in total read against the difference in confirmation cost.

As the input table is an order of magnitude larger than the spend table (307gb vs. 30.5gb), I'm hopeful this can give close to an order of magnitude improvement.

Due to consolidation the size change is input table -30.6GB and spend table +18.4GB, even with the additional link. There's also another savings in that the puts table can be reduced -2GB by making it a slab table and using the 4 byte vs. 5 byte spend link vs. 5 byte input link. So a net reduction of 14.2GB and an order of magnitude reduction in the paging cost for entry into the confirmation query. I'm hopeful this gets the confirmation query in rage, at least under the assumption of sufficient RAM.

@evoskuil @pmienk This 90 day limitation from slack is really annoying. They also don't offer any options for open source projects. https://app.slack.com/plans/ We lose a lot of useful information. Should we consider alternatives?

Topic: Dev Weekly Status Time: April 27, 2023 01:00pm Pacific Time (US and Canada) Join Zoom Meeting https://us05web.zoom.us/j/87666370902?pwd=bEZDUlJ0MGJ5V3dVMUhVdHl5QzdFdz09 Meeting ID: 876 6637 0902 Passcode: 85U0bF

I've merged the changes described above, and am performing a full sync. Sync time is reduced slightly as a consequence of collapsing the redundant fields. Once sync is complete I'll be able to measure the change to confirmation.

New schema is 97.8% the archive size of the previous. This is the result of collapsing the redundant search keys (7 bytes per non-coinbase input), adding a 5 byte link per input from spend to input, and reducing the puts.input link size from 5 to 4 bytes (input to spend link). This archive is 100.302% the size of the original normalized schema. Sync time is 99% of the previous run.

The new (unguarded sync) model was clearly outperforming the previous (both unguarded and guarded) with full blocks by more than 1%, but there was a remap of the 300gb inputs table toward the end because I slightly underestimated its full size.

Numbers are coming in and it looked at first like this might have been the order of magnitude change I was looking for, but the time benefit was entirely within the smaller blocks range. Looks like the net savings will be about 1.1 hours, putting completion for confirm at 6.5 hours. However the disk I/O went form a consistent 25mb/sec to a consistent 3mb/sec, so it's certainly a big improvement. Will still need to measure the cost in terms of reading out transactions, which I expect will be slightly higher.

Still holding at ~3mb/sec I/O, and improving a little over the previous model at higher block densities.

Final report, material reduction, 73% of previous (5.2 vs. 7.2 hours).

Just ran a quick isolated test on two simple tables using a stream reader/writer replacement that cuts out the iostream and operates directly over the memory address. This is a trivial object construction on each individual read/write just as the stream reader/writer were. The query time over the full chain (all headers) is 38% of original. If this advantage carries through the other queries and data sizes, as I expect it will since the size of data is really a consequence of quantity instances not of more bytes per instance, then this will cut confirmation to ~2hrs. Confirmation is hardly hitting the disk at all now, so I'm very hopeful. I expect it to improve tx read and write proportionally as well. If so and not peer limited that would reduce sequential single peer sync time to 4 hours and would reduce sequential full chain read time to 2 hours. These are numbers that are well within limits for our targets given concurrency.

The set_strong query is the only action required upon block confirmation. This took 18.7 minutes using iostream reader/writers, now takes 6.6 minutes (35%) using simple pointer-based reader/writers.

This is is_confirmable and set_strong queries combined as pointer vs. iostreams (incremental cost relative to data size). At about 50% completion it's holding steady at about 44%. Not quite the 38% I hoped for, but this should complete at 2.5 hours. Also there is really no perceptible disk activity despite reads across the full archive of indexes.

Total confirmation time, 2 hours 15 mins.

I'm going to generalize the non-stream reader/writer and move it into system with some testing. Since all chain and message objects de/serialize against the same read/writer interface, this can just implement the full interface and thus provides a significant performance improvement for not only the store object serializations (such as input, witness and output) but also network I/O. I'd expect that to more than double the single thread full sync (assuming peer capacity) and also full store read (which is required for validation).