From d7aa4fc760173d8a5604ea2aed3bc461d1bfd683 Mon Sep 17 00:00:00 2001 From: kevin Heifner Date: Sat, 18 Apr 2026 20:34:51 -0500 Subject: [PATCH 1/4] PerformanceHarness: use trace_api/get_actions for post-test trx extraction queryBlockTrxData previously called trace_api/get_block per block, which serialized the entire block including base58-encoded signatures (OpenSSL BN_div alloc storm - heaptrack showed ~5.7M OPENSSL_malloc calls on a 5k TPS 30s test). The harness only needs trx id, block num/time, cpu/net usage, and the block header - signatures are never consulted. Switch to two lightweight endpoints: chain/get_block_info for block header and trace_api/get_actions (filtered to the userTrxData's configured action name) for per-action data. Action-name filter is derived from userTrxDataDict so all test variants (transfer, cpu, ram, net, newaccount, doit, etc.) work out of the box, and onblock trxs are dropped server-side. Measured: ~40% reduction in post-test harness overhead for a 50k TPS 90s run (462s -> ~276s of non-test time). --- .../performance_test_basic.py | 52 ++++++++++++++----- 1 file changed, 39 insertions(+), 13 deletions(-) diff --git a/tests/PerformanceHarness/performance_test_basic.py b/tests/PerformanceHarness/performance_test_basic.py index 3d647da69b..b00683a793 100755 --- a/tests/PerformanceHarness/performance_test_basic.py +++ b/tests/PerformanceHarness/performance_test_basic.py @@ -305,24 +305,50 @@ def isOnBlockTransaction(self, transaction): return True def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum, endBlockNum): + # Use trace_api/get_actions for trx-level data and chain/get_block_info for block metadata. + # The old trace_api/get_block serialized the entire block (including base58-encoded + # signatures - OpenSSL BN_div alloc storm) even though the harness only needs trx id, + # block num/time, cpu/net usage, and the block header. + # Filter by the configured action name (transfer/cpu/ram/net/newaccount/doit/...) so + # onblock and other unrelated trxs are skipped server-side without base58 work. + actionFilter = None + if getattr(self, 'userTrxDataDict', None): + cfgActions = self.userTrxDataDict.get('actions') or [] + if cfgActions: + actionFilter = cfgActions[0].get('actionName') for blockNum in range(startBlockNum, endBlockNum + 1): blockCpuTotal, blockNetTotal, blockTransactionTotal = 0, 0, 0 - block = node.processUrllibRequest("trace_api", "get_block", {"block_num":blockNum}, silentErrors=False, exitOnError=True) + blockInfo = node.processUrllibRequest("chain", "get_block_info", {"block_num":blockNum}, silentErrors=False, exitOnError=True) + actionsQuery = {"block_num_start": blockNum, "block_num_end": blockNum} + if actionFilter: + actionsQuery["action"] = actionFilter + actionsResp = node.processUrllibRequest("trace_api", "get_actions", actionsQuery, silentErrors=False, exitOnError=True) btdf_append_write = self.fileOpenMode(blockTrxDataPath) with open(blockTrxDataPath, btdf_append_write) as trxDataFile: - for trx in block['payload']['transactions']: - if not self.isOnBlockTransaction(trx): - trx_data = trxData(blockNum=trx["block_num"], cpuUsageUs=trx["cpu_usage_us"], - netUsageUs=trx["net_usage_words"], blockTime=trx["block_time"]) - self.data.trxDict.update(dict([(trx["id"], trx_data)])) - [ trxDataFile.write(f"{trx['id']},{trx['block_num']},{trx['block_time']},{trx['cpu_usage_us']},{trx['net_usage_words']},{trx['actions']}\n") ] - blockCpuTotal += trx["cpu_usage_us"] - blockNetTotal += trx["net_usage_words"] - blockTransactionTotal += 1 - block_data = blockData(blockId=block["payload"]["id"], blockNum=block['payload']['number'], + seen = set() # dedup if a trx somehow has multiple matching actions + for action in actionsResp['payload']['actions']: + # If no action filter configured, still skip onblock explicitly. + if not actionFilter and action.get('account') == 'sysio' and action.get('name') == 'onblock': + continue + trxId = action['trx_id'] + if trxId in seen: + continue + seen.add(trxId) + cpu = action.get('cpu_usage_us', 0) or 0 + net = action.get('net_usage', 0) or 0 + trx_data = trxData(blockNum=action['block_num'], cpuUsageUs=cpu, + netUsageUs=net, blockTime=action['block_time']) + self.data.trxDict.update({trxId: trx_data}) + trxDataFile.write(f"{trxId},{action['block_num']},{action['block_time']},{cpu},{net},\n") + blockCpuTotal += cpu + blockNetTotal += net + blockTransactionTotal += 1 + block_data = blockData(blockId=blockInfo["payload"]["id"], + blockNum=blockInfo['payload']['block_num'], transactions=blockTransactionTotal, net=blockNetTotal, cpu=blockCpuTotal, - producer=block["payload"]["producer"], status=block["payload"]["status"], - _timestamp=block["payload"]["timestamp"]) + producer=blockInfo["payload"]["producer"], + status="executed", + _timestamp=blockInfo["payload"]["timestamp"]) self.data.blockList.append(block_data) self.data.blockDict[str(blockNum)] = block_data bdf_append_write = self.fileOpenMode(blockDataPath) From c12471d559e74e0a12ce54d3753f6afbf534a05c Mon Sep 17 00:00:00 2001 From: kevin Heifner Date: Fri, 8 May 2026 10:18:36 -0500 Subject: [PATCH 2/4] PerformanceHarness: read per-trx cpu/net from get_actions trx_* fields get_actions emits per-action cpu_usage_us / net_usage and per-trx trx_cpu_usage_us / trx_net_usage_words on each action variant. The harness wants per-trx totals, so read the trx_* fields: * multi-action trxs no longer undercount when the filter only catches one of their actions * net is back in words (ceil(bytes / 8)) matching the trace_api/get_block shape the harness used before d7aa4fc760 The dedup-by-trx_id loop still prunes duplicate entries when a trx has multiple actions matching the filter. --- tests/PerformanceHarness/performance_test_basic.py | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/tests/PerformanceHarness/performance_test_basic.py b/tests/PerformanceHarness/performance_test_basic.py index b00683a793..d1f52afe80 100755 --- a/tests/PerformanceHarness/performance_test_basic.py +++ b/tests/PerformanceHarness/performance_test_basic.py @@ -311,6 +311,10 @@ def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum # block num/time, cpu/net usage, and the block header. # Filter by the configured action name (transfer/cpu/ram/net/newaccount/doit/...) so # onblock and other unrelated trxs are skipped server-side without base58 work. + # Per-trx cpu/net come from trx_cpu_usage_us / trx_net_usage_words on each action variant + # (the parent transaction's totals); the action-level cpu_usage_us / net_usage would + # undercount multi-action trxs and use different units (action net_usage is bytes; trx + # net_usage_words is ceil(bytes / 8)). actionFilter = None if getattr(self, 'userTrxDataDict', None): cfgActions = self.userTrxDataDict.get('actions') or [] @@ -325,7 +329,7 @@ def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum actionsResp = node.processUrllibRequest("trace_api", "get_actions", actionsQuery, silentErrors=False, exitOnError=True) btdf_append_write = self.fileOpenMode(blockTrxDataPath) with open(blockTrxDataPath, btdf_append_write) as trxDataFile: - seen = set() # dedup if a trx somehow has multiple matching actions + seen = set() # one trxData entry per trx even if multiple actions match the filter for action in actionsResp['payload']['actions']: # If no action filter configured, still skip onblock explicitly. if not actionFilter and action.get('account') == 'sysio' and action.get('name') == 'onblock': @@ -334,8 +338,8 @@ def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum if trxId in seen: continue seen.add(trxId) - cpu = action.get('cpu_usage_us', 0) or 0 - net = action.get('net_usage', 0) or 0 + cpu = action.get('trx_cpu_usage_us', 0) or 0 + net = action.get('trx_net_usage_words', 0) or 0 trx_data = trxData(blockNum=action['block_num'], cpuUsageUs=cpu, netUsageUs=net, blockTime=action['block_time']) self.data.trxDict.update({trxId: trx_data}) From 09b31cefcb5c8f766d546c43d96144a3c17a2278 Mon Sep 17 00:00:00 2001 From: kevin Heifner Date: Fri, 8 May 2026 14:06:54 -0500 Subject: [PATCH 3/4] PerformanceHarness: read block_status from get_actions, fallback to get_block on empty Replace the hardcoded status="executed" (which was a transaction-status concept misapplied to a block row) with the real block finality from trace_api. All actions in a block share the same block_status, so capture it once from the first action. Blocks where the configured action filter dropped every entry (typically the leading/trailing ramp window) have no action to read from. Fall back to trace_api/get_block on those, so finality continues to come from trace_api's data log rather than mixing in a chain/get_info LIB read. Cost is bounded -- empty/onblock-only blocks have no trx signatures to base58-encode, so the heavy serialization the surrounding refactor avoided does not show up here either. --- .../performance_test_basic.py | 19 ++++++++++++++++++- 1 file changed, 18 insertions(+), 1 deletion(-) diff --git a/tests/PerformanceHarness/performance_test_basic.py b/tests/PerformanceHarness/performance_test_basic.py index d1f52afe80..0d27791008 100755 --- a/tests/PerformanceHarness/performance_test_basic.py +++ b/tests/PerformanceHarness/performance_test_basic.py @@ -315,6 +315,11 @@ def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum # (the parent transaction's totals); the action-level cpu_usage_us / net_usage would # undercount multi-action trxs and use different units (action net_usage is bytes; trx # net_usage_words is ceil(bytes / 8)). + # Block finality (irreversible/pending) comes from block_status on each action -- trace_api + # is the single source of truth so we never mix in a chain/get_info LIB read that could + # disagree with what the trace data reflects. For blocks where the action filter dropped + # everything (typically the leading/trailing ramp window), fall back to trace_api/get_block + # for that one block: empty blocks carry no harness-action trxs so the payload is small. actionFilter = None if getattr(self, 'userTrxDataDict', None): cfgActions = self.userTrxDataDict.get('actions') or [] @@ -322,6 +327,7 @@ def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum actionFilter = cfgActions[0].get('actionName') for blockNum in range(startBlockNum, endBlockNum + 1): blockCpuTotal, blockNetTotal, blockTransactionTotal = 0, 0, 0 + blockStatus = None blockInfo = node.processUrllibRequest("chain", "get_block_info", {"block_num":blockNum}, silentErrors=False, exitOnError=True) actionsQuery = {"block_num_start": blockNum, "block_num_end": blockNum} if actionFilter: @@ -338,6 +344,9 @@ def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum if trxId in seen: continue seen.add(trxId) + # All actions in a block share the same block_status; capture once. + if blockStatus is None: + blockStatus = action.get('block_status') cpu = action.get('trx_cpu_usage_us', 0) or 0 net = action.get('trx_net_usage_words', 0) or 0 trx_data = trxData(blockNum=action['block_num'], cpuUsageUs=cpu, @@ -347,11 +356,19 @@ def queryBlockTrxData(self, node, blockDataPath, blockTrxDataPath, startBlockNum blockCpuTotal += cpu blockNetTotal += net blockTransactionTotal += 1 + if blockStatus is None: + # No harness-relevant action in this block. Fall back to trace_api/get_block so + # the row's status still comes from trace_api's data log rather than mixing in a + # different source. Cost is bounded -- empty/onblock-only blocks have no trx + # signatures to base58-encode. + blockResp = node.processUrllibRequest("trace_api", "get_block", {"block_num": blockNum}, + silentErrors=False, exitOnError=True) + blockStatus = blockResp['payload'].get('status', 'unknown') block_data = blockData(blockId=blockInfo["payload"]["id"], blockNum=blockInfo['payload']['block_num'], transactions=blockTransactionTotal, net=blockNetTotal, cpu=blockCpuTotal, producer=blockInfo["payload"]["producer"], - status="executed", + status=blockStatus, _timestamp=blockInfo["payload"]["timestamp"]) self.data.blockList.append(block_data) self.data.blockDict[str(blockNum)] = block_data From 16ad8167039f46d64f2a0cc804b73fae134789c8 Mon Sep 17 00:00:00 2001 From: kevin Heifner Date: Fri, 8 May 2026 17:53:44 -0500 Subject: [PATCH 4/4] PerformanceHarness: tolerate missing 'Z' on block timestamp trace_api/get_block emits ISO8601 with a 'Z' suffix; chain/get_block_info serializes block_timestamp_type via fc::to_iso_string() with no zone marker. The setter blindly stripped the last character, which truncated '.500' to '.50' for get_block_info. Strip 'Z' only when present so sub-second precision survives either source and parsing tolerates either shape. --- tests/PerformanceHarness/log_reader.py | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/tests/PerformanceHarness/log_reader.py b/tests/PerformanceHarness/log_reader.py index be11a9f472..de39d200ac 100644 --- a/tests/PerformanceHarness/log_reader.py +++ b/tests/PerformanceHarness/log_reader.py @@ -144,11 +144,16 @@ def calcdTimeEpoch(self): @timestamp.setter def timestamp(self, time: str): - self._timestamp = time[:-1] + # Sources differ on the trailing 'Z': trace_api/get_block emits ISO8601 with a 'Z' + # suffix, while chain/get_block_info serializes block_timestamp_type via fc's + # to_iso_string() with no zone marker. Strip 'Z' only when it is present so we keep + # full sub-second precision (e.g. '.500') regardless of which endpoint produced the + # value, and so parsing tolerates either shape. # When we no longer support Python 3.6, would be great to update to use this - # self._calcdTimeEpoch = datetime.fromisoformat(time[:-1]).timestamp() - #Note block timestamp formatted like: '2022-09-30T16:48:13.500Z', but 'Z' is not part of python's recognized iso format, so strip it off the end - self._calcdTimeEpoch = datetime.strptime(time[:-1], "%Y-%m-%dT%H:%M:%S.%f").timestamp() + # self._calcdTimeEpoch = datetime.fromisoformat(stripped).timestamp() + stripped = time[:-1] if time.endswith('Z') else time + self._timestamp = stripped + self._calcdTimeEpoch = datetime.strptime(stripped, "%Y-%m-%dT%H:%M:%S.%f").timestamp() @timestamp.deleter def timestamp(self):