traceChain individual blocks don't appear to be traced concurrently

[hub-il]

System information

Geth version: Geth/v1.11.5-stable/linux-amd64/go1.19.1
OS & Version: Linux

Expected behaviour

Using Websockets to send the request below:
{"jsonrpc": "2.0", "id": 1, "method": "debug_subscribe", "params": ["traceChain", "0x1090f9e", "0x1091386", {"tracer": "callTracer", "tracerConfig":{"withLog": true, "onlyTopCall": true}}]}

Based on release notes for geth 1.8 individual blocks are traced concurrently, so total tracing time gets proportionally lower the more CPU cores you throw at it

I would expect to get the blocks back as they are finished (not numerical order) but instead I am getting them back as if they have been processed consecutively (in numerical order) and not concurrently.

Checked the htop on the machine and its not obvious that multiple cores are being used.

Actual behaviour

The logs appear to show the blocks being processes concurrently but they are returned consecutively

INFO [06-23|17:16:25.254] Imported new potential chain segment     number=17,543,695 hash=6e2637..f9b8a8 blocks=1 txs=142  mgas=12.679  elapsed=177.390ms        mgasps=71.477   dirty=0.00B
INFO [06-23|17:16:25.372] Chain head was updated                   number=17,543,695 hash=6e2637..f9b8a8 root=dc41c4..0d19bb elapsed=2.472104ms
INFO [06-23|17:16:34.465] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,368 transactions=57710 elapsed=40m8.054471218s
INFO [06-23|17:16:36.242] Imported new potential chain segment     number=17,543,696 hash=7901be..b4709f blocks=1 txs=158  mgas=19.245  elapsed=190.943ms        mgasps=100.789  dirty=0.00B
INFO [06-23|17:16:36.360] Chain head was updated                   number=17,543,696 hash=7901be..b4709f root=947e47..8e8861 elapsed=2.587225ms
INFO [06-23|17:16:43.209] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,370 transactions=58064 elapsed=40m16.79914958s
INFO [06-23|17:16:48.634] Imported new potential chain segment     number=17,543,697 hash=1c6b1d..31144a blocks=1 txs=111  mgas=11.044  elapsed=109.947ms        mgasps=100.449  dirty=0.00B
INFO [06-23|17:16:48.757] Chain head was updated                   number=17,543,697 hash=1c6b1d..31144a root=bffbb5..1fad01 elapsed=2.177177ms
INFO [06-23|17:16:51.482] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,372 transactions=58418 elapsed=40m25.071928655s
INFO [06-23|17:17:00.613] Imported new potential chain segment     number=17,543,698 hash=9c20a9..1eaddd blocks=1 txs=132  mgas=12.089  elapsed=622.454ms        mgasps=19.422   dirty=0.00B
INFO [06-23|17:17:00.754] Chain head was updated                   number=17,543,698 hash=9c20a9..1eaddd root=e50296..1b684b elapsed=2.414694ms
INFO [06-23|17:17:00.936] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,374 transactions=58723 elapsed=40m34.526065063s
INFO [06-23|17:17:11.232] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,376 transactions=59058 elapsed=40m44.82201701s
INFO [06-23|17:17:12.209] Imported new potential chain segment     number=17,543,699 hash=d4fbe2..5edfb0 blocks=1 txs=148  mgas=9.905   elapsed=204.320ms        mgasps=48.480   dirty=0.00B
INFO [06-23|17:17:12.329] Chain head was updated                   number=17,543,699 hash=d4fbe2..5edfb0 root=c1beb2..dc1bcf elapsed=2.101061ms
INFO [06-23|17:17:20.122] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,378 transactions=59362 elapsed=40m53.71161689s
INFO [06-23|17:17:25.288] Imported new potential chain segment     number=17,543,700 hash=e41a2f..dea179 blocks=1 txs=198  mgas=24.591  elapsed=377.666ms        mgasps=65.114   dirty=0.00B
INFO [06-23|17:17:25.413] Chain head was updated                   number=17,543,700 hash=e41a2f..dea179 root=425588..97f568 elapsed=3.35617ms
INFO [06-23|17:17:29.817] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,380 transactions=59712 elapsed=41m3.407083089s
INFO [06-23|17:17:37.180] Imported new potential chain segment     number=17,543,701 hash=c9a7f1..88c6de blocks=1 txs=123  mgas=8.615   elapsed=61.119ms         mgasps=140.956  dirty=0.00B
INFO [06-23|17:17:37.299] Chain head was updated                   number=17,543,701 hash=c9a7f1..88c6de root=b7a43a..9c6d92 elapsed=1.696643ms
INFO [06-23|17:17:38.736] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,382 transactions=60127 elapsed=41m12.325395568s
INFO [06-23|17:17:47.594] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,384 transactions=60428 elapsed=41m21.183476735s
INFO [06-23|17:17:47.762] Imported new potential chain segment     number=17,543,702 hash=cacbd4..4952f0 blocks=1 txs=105  mgas=11.685  elapsed=100.774ms        mgasps=115.950  dirty=0.00B
INFO [06-23|17:17:47.880] Chain head was updated                   number=17,543,702 hash=cacbd4..4952f0 root=0db56f..ba23e8 elapsed=1.458555ms
INFO [06-23|17:17:55.798] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,386 transactions=60715 elapsed=41m29.387174637s
INFO [06-23|17:18:00.910] Imported new potential chain segment     number=17,543,703 hash=8c6035..f0d2f3 blocks=1 txs=155  mgas=15.640  elapsed=619.435ms        mgasps=25.249   dirty=0.00B
INFO [06-23|17:18:01.031] Chain head was updated                   number=17,543,703 hash=8c6035..f0d2f3 root=4132db..747ba1 elapsed=2.793594ms
INFO [06-23|17:18:04.592] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,388 transactions=61036 elapsed=41m38.181657188s
INFO [06-23|17:18:13.447] Imported new potential chain segment     number=17,543,704 hash=b79d15..25a857 blocks=1 txs=189  mgas=16.495  elapsed=113.308ms        mgasps=145.574  dirty=0.00B
INFO [06-23|17:18:13.568] Chain head was updated                   number=17,543,704 hash=b79d15..25a857 root=144cdc..b059ec elapsed=3.044812ms
INFO [06-23|17:18:14.751] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,390 transactions=61404 elapsed=41m48.340365353s
INFO [06-23|17:18:25.571] Imported new potential chain segment     number=17,543,705 hash=49252e..c16753 blocks=1 txs=181  mgas=15.017  elapsed=184.303ms        mgasps=81.479   dirty=0.00B
INFO [06-23|17:18:25.692] Chain head was updated                   number=17,543,705 hash=49252e..c16753 root=08949d..85a6ec elapsed=2.617104ms
INFO [06-23|17:18:26.263] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,392 transactions=61835 elapsed=41m59.852522838s
INFO [06-23|17:18:35.601] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,394 transactions=62151 elapsed=42m9.190844819s
INFO [06-23|17:18:38.030] Imported new potential chain segment     number=17,543,706 hash=076271..18b519 blocks=1 txs=131  mgas=12.509  elapsed=148.437ms        mgasps=84.272   dirty=0.00B
INFO [06-23|17:18:38.129] Chain head was updated                   number=17,543,706 hash=076271..18b519 root=4dd074..8bceda elapsed=2.509196ms
INFO [06-23|17:18:48.473] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,397 transactions=62666 elapsed=42m22.0628205s
INFO [06-23|17:18:48.813] Imported new potential chain segment     number=17,543,707 hash=02545d..523d9e blocks=1 txs=146  mgas=13.739  elapsed=159.549ms        mgasps=86.113   dirty=0.00B
INFO [06-23|17:18:48.910] Chain head was updated                   number=17,543,707 hash=02545d..523d9e root=b7a4a4..02fd97 elapsed=3.286797ms
INFO [06-23|17:18:56.540] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,399 transactions=63008 elapsed=42m30.129318607s
INFO [06-23|17:19:00.435] Imported new potential chain segment     number=17,543,708 hash=282fdd..37caf3 blocks=1 txs=159  mgas=13.072  elapsed=252.967ms        mgasps=51.676   dirty=0.00B
INFO [06-23|17:19:00.535] Chain head was updated                   number=17,543,708 hash=282fdd..37caf3 root=457f08..c66451 elapsed=2.308169ms
INFO [06-23|17:19:04.931] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,401 transactions=63331 elapsed=42m38.520618261s
INFO [06-23|17:19:12.291] Imported new potential chain segment     number=17,543,709 hash=2cf4f6..64598d blocks=1 txs=134  mgas=12.180  elapsed=129.125ms        mgasps=94.330   dirty=0.00B
INFO [06-23|17:19:12.389] Chain head was updated                   number=17,543,709 hash=2cf4f6..64598d root=d83715..9bcf9f elapsed=2.686031ms
INFO [06-23|17:19:15.214] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,403 transactions=63734 elapsed=42m48.804066966s
INFO [06-23|17:19:25.553] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,406 transactions=64144 elapsed=42m59.143130881s
INFO [06-23|17:19:25.609] Imported new potential chain segment     number=17,543,710 hash=6b0fb5..4aeb19 blocks=1 txs=179  mgas=13.009  elapsed=181.641ms        mgasps=71.620   dirty=0.00B
INFO [06-23|17:19:25.708] Chain head was updated                   number=17,543,710 hash=6b0fb5..4aeb19 root=1c4d24..f29b1b elapsed=2.54656ms
INFO [06-23|17:19:37.335] Imported new potential chain segment     number=17,543,711 hash=bcf3bf..22f868 blocks=1 txs=191  mgas=20.731  elapsed=317.463ms        mgasps=65.302   dirty=0.00B

Steps to reproduce the behaviour

import asyncio
import websockets
import json
import struct
import sys
import datetime

def float_to_hex(f):
    hex_str = "0x{:x}".format(f)
    return hex_str

def call_trace_blocks(range_start, range_end):
    
    start_range = min([range_start, range_end])
    end_range = max([range_start, range_end])

    block_range_count = end_range-start_range
    print(f"tracing {block_range_count} blocks")

    block_start_hex = float_to_hex(start_range)
    block_end_hex = float_to_hex(end_range)

    request_str = '{"jsonrpc": "2.0", "id": 1, "method": "debug_subscribe", "params": ["traceChain", "' + block_start_hex + '", "' + block_end_hex + '", {"tracer": "callTracer", "tracerConfig":{"withLog": true, "onlyTopCall": true}}]}'

    eth_ws_url = 'localhost:8546'
    start_datetime_obj = datetime.datetime.now()
    print(f"started processing")
    print(f"request: {request_str}")

    async def ws_block_data():
        async with websockets.connect(f'ws://{eth_ws_url}', ping_timeout=60*30) as websocket:
            request = request_str

            await websocket.send(request)

            record_count = 0
            while True:
                trace_data_json = await websocket.recv()
                if trace_data_json != None:
                    trace_data_dict = json.loads(trace_data_json)
                    #print(trace_data_dict)
                    if "error" in trace_data_dict.keys():
                        print(f"error: {trace_data_dict['error']}")
                        break
                    
                    if 'params' in trace_data_dict:
                        record_count += 1
                        end_time_obj = datetime.datetime.now()
                        total_seconds = (end_time_obj-start_datetime_obj).total_seconds()
                        print(f"{record_count}: {int(trace_data_dict['params']['result']['block'], 16)}, len(traces): {len(trace_data_dict['params']['result']['traces'])}, {round(total_seconds/60, 4)} total minutes, {round(record_count/total_seconds, 3)} blocks/sec avg")
                        if record_count == block_range_count:
                            print(f"processed all {block_range_count} blocks in {round(total_seconds/60, 3)} minutes, {round(record_count/total_seconds, 3)} blocks/sec avg")
                            print(f"{round(record_count/total_seconds, 3)} blocks/sec avg")
                            print(f"{round(record_count/(total_seconds/60), 4)} blocks/min avg")
                            break

    asyncio.get_event_loop().run_until_complete(ws_block_data())

block_ranges = (17371038, 17372038)
call_trace_blocks(block_ranges[0], block_ranges[1])

[jsvisa]

TraceChain is a producer/consumer model:

1. producer runs in one goroutine,
2. consumers run at most runtime.NumCPU goroutines,
3. producer and consumers communicate with channel,
4. the producer sequential traversals the [from, to] block range, and fetches the block's statedb then sends it as a task into the channel
5. consumers consuming all available tasks

And TraceChain is IO-heavy tasks, from the logs that you provided:

INFO [06-23|17:16:34.465] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,368 transactions=57710 elapsed=40m8.054471218s
INFO [06-23|17:16:43.209] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,370 transactions=58064 elapsed=40m16.79914958s
INFO [06-23|17:16:51.482] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,372 transactions=58418 elapsed=40m25.071928655s

The producer handles the blocks in 4s/block, that's too slow. So in my opinion, it's the bottleneck of the producer, and maybe the root cause is the IO usage. Could you please identify the usage of IOutil(eg: iostat -x 1)

[s1na]

TraceChain had a change to its concurrency model recently: #24283. Basically in you're example you're using a native tracer, and in that case we process things serially. To add some context to @jsvisa's answer:

• The reason we can't process blocks completely independently of eachother is state. So we start building up the state from later blocks from previous ones. The only case we could do complete concurrent tracing of blocks is for archive node but right now we don't have a special optimization for only archive nodes.
• Why we decided to have a different behavior for JS vs non-JS tracers is that JS tracers have high overhead. It was faster to have a separate thread process blocks with tracing disabled and feed the state it builds up to other worker threads that then trace each block. However in non-JS tracers the overhead is low enough that having this producer-consumer model doesn't make sense anymore.

Are you running an archive node?

[hub-il]

Are you running an archive node?

Yes we are running an archive node. It is fully synced.

[hub-il]

The producer handles the blocks in 4s/block, that's too slow. So in my opinion, it's the bottleneck of the producer, and maybe the root cause is the IO usage. Could you please identify the usage of IOutil(eg: iostat -x 1)

Its no problem for us to move to faster storage to help the IO but the issue I am having specifically is that although the release notes of 1.8 make is seem like the blocks should processed concurrently and the logs appear to show that, they are being sent consecutively. If we moved to fast NVME it seems that we are still going to get the blocks consecutively not when they are done being traced.

It seems that based on the reply of @s1na this is expected and the release notes are either incorrect or unclear for the traceChain method.

[s1na]

Please excuse my last comment. I got confused. What we changed was the behavior of traceBlock in #24283. It didn't help the title of that PR was misleading as well. I fixed that now.

traceChain is indeed still processing blocks concurrently. You are correct in your observation that the results are in sequence and the logs indicate serial processing. The reason is traceChain sends the result in the order of block number, waiting if necessary until the result for the next block in turn to become ready.

The producer handles the blocks in 4s/block, that's too slow.

I'm wondering if that's because of statedb.Copy(). Update: no statedb.Copy should be fast.

[s1na]

The producer handles the blocks in 4s/block, that's too slow.

Thinking about this more, the producer could be blocked on the channel send. I.e. 4s is the rate of tracing a block after which a thread becomes available to process the next.

It would help to see the logs from right when traceChain operation was started.

[hub-il]

It would help to see the logs from right when traceChain operation was started.

Not sure how much in the way of logs you think would be helpful but here is what it looks like when it starts.

INFO [06-27|15:22:13.907] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,038 transactions=0       elapsed="1.17µs"
INFO [06-27|15:22:24.975] Imported new potential chain segment     number=17,571,544 hash=83f282..a89cb0 blocks=1 txs=140  mgas=18.756  elapsed=201.831ms          mgasps=92.927   dirty=0.00B
INFO [06-27|15:22:25.103] Chain head was updated                   number=17,571,544 hash=83f282..a89cb0 root=3dad4f..af0c70 elapsed=2.862658ms
INFO [06-27|15:22:36.365] Imported new potential chain segment     number=17,571,545 hash=8fcfbf..5f3b07 blocks=1 txs=122  mgas=10.307  elapsed=128.557ms          mgasps=80.175   dirty=0.00B
INFO [06-27|15:22:36.491] Chain head was updated                   number=17,571,545 hash=8fcfbf..5f3b07 root=442dfd..057133 elapsed=1.757861ms
INFO [06-27|15:22:47.321] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,040 transactions=378     elapsed=33.413984368s
INFO [06-27|15:22:47.613] Imported new potential chain segment     number=17,571,546 hash=d1d91a..dbce1b blocks=1 txs=148  mgas=12.626  elapsed=99.595ms           mgasps=126.775  dirty=0.00B
INFO [06-27|15:22:47.746] Chain head was updated                   number=17,571,546 hash=d1d91a..dbce1b root=cb8563..fa928e elapsed=2.472603ms
INFO [06-27|15:23:00.297] Imported new potential chain segment     number=17,571,547 hash=c34602..6e90bd blocks=1 txs=163  mgas=15.379  elapsed=149.050ms          mgasps=103.182  dirty=0.00B
INFO [06-27|15:23:00.423] Chain head was updated                   number=17,571,547 hash=c34602..6e90bd root=a527e1..f21392 elapsed=2.149626ms
INFO [06-27|15:23:04.224] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,041 transactions=545     elapsed=50.316994002s
INFO [06-27|15:23:12.703] Imported new potential chain segment     number=17,571,548 hash=7005b5..d47ab8 blocks=1 txs=171  mgas=14.814  elapsed=280.389ms          mgasps=52.834   dirty=0.00B
INFO [06-27|15:23:12.825] Chain head was updated                   number=17,571,548 hash=7005b5..d47ab8 root=aeb8cb..4e8ba3 elapsed=2.084436ms
INFO [06-27|15:23:23.257] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,042 transactions=718     elapsed=1m9.350298174s
INFO [06-27|15:23:24.379] Imported new potential chain segment     number=17,571,549 hash=0f423f..98c2e6 blocks=1 txs=139  mgas=13.426  elapsed=194.914ms          mgasps=68.883   dirty=0.00B
INFO [06-27|15:23:24.482] Chain head was updated                   number=17,571,549 hash=0f423f..98c2e6 root=ccd91e..5d60db elapsed=4.010565ms
INFO [06-27|15:23:37.029] Imported new potential chain segment     number=17,571,550 hash=020624..1cbdd5 blocks=1 txs=153  mgas=13.056  elapsed=506.459ms          mgasps=25.778   dirty=0.00B
INFO [06-27|15:23:37.134] Chain head was updated                   number=17,571,550 hash=020624..1cbdd5 root=492c2a..8a1dab elapsed=2.40735ms
INFO [06-27|15:23:38.508] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,043 transactions=895     elapsed=1m24.600672638s
INFO [06-27|15:23:48.527] Imported new potential chain segment     number=17,571,551 hash=14269d..f3c3d6 blocks=1 txs=196  mgas=14.590  elapsed=347.629ms          mgasps=41.971   dirty=0.00B
INFO [06-27|15:23:48.629] Chain head was updated                   number=17,571,551 hash=14269d..f3c3d6 root=a095ad..e0c916 elapsed=2.915637ms
INFO [06-27|15:23:59.288] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,044 transactions=1069    elapsed=1m45.381242489s
INFO [06-27|15:24:00.239] Imported new potential chain segment     number=17,571,552 hash=4925f2..49ae10 blocks=1 txs=153  mgas=14.142  elapsed=155.376ms          mgasps=91.021   dirty=0.00B
INFO [06-27|15:24:00.344] Chain head was updated                   number=17,571,552 hash=4925f2..49ae10 root=dc45d2..fe8291 elapsed=2.220977ms
INFO [06-27|15:24:13.151] Imported new potential chain segment     number=17,571,553 hash=46032c..270173 blocks=1 txs=159  mgas=16.348  elapsed=326.416ms          mgasps=50.083   dirty=0.00B
INFO [06-27|15:24:13.259] Chain head was updated                   number=17,571,553 hash=46032c..270173 root=49a82b..1573df elapsed=3.254486ms
INFO [06-27|15:24:14.285] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,045 transactions=1202    elapsed=2m0.37776568s
INFO [06-27|15:24:22.938] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,046 transactions=1404    elapsed=2m9.030817832s
INFO [06-27|15:24:24.035] Imported new potential chain segment     number=17,571,554 hash=6c6ae1..4bb39b blocks=1 txs=136  mgas=13.170  elapsed=225.141ms          mgasps=58.495   dirty=0.00B
INFO [06-27|15:24:24.132] Chain head was updated                   number=17,571,554 hash=6c6ae1..4bb39b root=294f27..d0fc01 elapsed=1.843762ms
INFO [06-27|15:24:36.322] Imported new potential chain segment     number=17,571,555 hash=5c0564..886733 blocks=1 txs=186  mgas=13.898  elapsed=159.723ms          mgasps=87.010   dirty=0.00B
INFO [06-27|15:24:36.428] Chain head was updated                   number=17,571,555 hash=5c0564..886733 root=6ca757..de3280 elapsed=3.819827ms
INFO [06-27|15:24:41.970] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,047 transactions=1535    elapsed=2m28.062933527s
INFO [06-27|15:24:49.231] Imported new potential chain segment     number=17,571,556 hash=b882a7..dcf694 blocks=1 txs=173  mgas=14.280  elapsed=808.786ms          mgasps=17.656   dirty=0.00B
INFO [06-27|15:24:49.335] Chain head was updated                   number=17,571,556 hash=b882a7..dcf694 root=8abd25..548e16 elapsed=2.677539ms
INFO [06-27|15:24:52.055] Tracing chain segment                    start=17,371,038 end=17,372,038 current=17,371,048 transactions=1792    elapsed=2m38.148558195s