From 9dae96271c50f0279035e4a10c00b8b03bf205fb Mon Sep 17 00:00:00 2001 From: Moray Grieve Date: Wed, 11 Dec 2024 14:18:01 +0000 Subject: [PATCH] Handling tx send failures (#388) * Handling failed sent transactions * Use actual sent * More txs_sent * Correct num data points --- src/python/ten/test/basetest.py | 9 +++++++++ tests/ten/ten_per_001/run.py | 2 +- tests/ten/ten_per_002/Input/client.py | 12 +++++------- tests/ten/ten_per_002/run.py | 12 +++++++----- tests/ten/ten_per_003/Input/client.py | 11 +++++------ tests/ten/ten_per_003/run.py | 11 +++++++---- tests/ten/ten_per_004/Input/client.py | 11 +++++------ tests/ten/ten_per_004/run.py | 11 +++++++---- tests/ten/ten_per_005/Input/storage_client.py | 9 ++++----- tests/ten/ten_per_005/run.py | 9 ++++++--- tests/ten/ten_per_006/Input/client.py | 12 ++++-------- tests/ten/ten_per_006/run.py | 13 +++++++------ tests/ten/ten_per_010/run.py | 15 ++++++++------- tests/ten/ten_per_011/run.py | 15 ++++++++------- tests/ten/ten_per_012/run.py | 15 ++++++++------- 15 files changed, 91 insertions(+), 76 deletions(-) diff --git a/src/python/ten/test/basetest.py b/src/python/ten/test/basetest.py index 427a49e9..e7e96316 100644 --- a/src/python/ten/test/basetest.py +++ b/src/python/ten/test/basetest.py @@ -504,3 +504,12 @@ def ratio_failures(self, file, threshold=0.05): self.log.info('Ratio of failures is %.2f' % ratio) if ratio > threshold: self.addOutcome(FAILED, outcomeReason='Failure ratio > 0.05', abortOnError=False) return ratio + + def txs_sent(self, file): + """Search through a log for number of transactions sent. """ + regex = re.compile('Number of transactions sent = (?P.*)$', re.M) + with open(file, 'r') as fp: + for line in fp.readlines(): + result = regex.search(line) + if result is not None: return int(result.group('sent')) + return 0 \ No newline at end of file diff --git a/tests/ten/ten_per_001/run.py b/tests/ten/ten_per_001/run.py index 23b2f545..4a647124 100644 --- a/tests/ten/ten_per_001/run.py +++ b/tests/ten/ten_per_001/run.py @@ -8,7 +8,7 @@ class PySysTest(TenNetworkTest): - ITERATIONS = 5000 # number of iterations per client + ITERATIONS = 2048 # number of iterations per client def __init__(self, descriptor, outsubdir, runner): super().__init__(descriptor, outsubdir, runner) diff --git a/tests/ten/ten_per_002/Input/client.py b/tests/ten/ten_per_002/Input/client.py index 8787b861..967ecbbd 100644 --- a/tests/ten/ten_per_002/Input/client.py +++ b/tests/ten/ten_per_002/Input/client.py @@ -31,16 +31,14 @@ def run(name, chainId, web3, account, num_accounts, num_iterations, amount, gas_ logging.info('Bulk sending transactions to the network') receipts = [] - stats = [0,0] for tx in txs: try: receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1])) - stats[0] += 1 - except: - logging.error('Error sending raw transaction, sent = %d', len(receipts)) - stats[1] += 1 - - logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats)) + except Exception as e: + logging.error('Error sending raw transaction', e) + logging.warning('Continuing with smaller number of transactions ...') + break + logging.info('Number of transactions sent = %d', len(receipts)) logging.info('Waiting for last transaction') web3.eth.wait_for_transaction_receipt(receipts[-1][0], timeout=600) diff --git a/tests/ten/ten_per_002/run.py b/tests/ten/ten_per_002/run.py index 1a9a1e77..c6685bc9 100644 --- a/tests/ten/ten_per_002/run.py +++ b/tests/ten/ten_per_002/run.py @@ -33,9 +33,12 @@ def execute(self): pk2, conn2 = self.setup_client('client_two', funds_needed) self.run_client('client_one', pk1, conn1) self.run_client('client_two', pk2, conn2) + txs_sent = 0 for i in self.clients: - self.waitForGrep(file='client_%s.out' % i, expr='Client client_%s completed' % i, timeout=900) - self.ratio_failures(file=os.path.join(self.output, 'client_%s.out' % i)) + stdout = os.path.join(self.output,'client_%s.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=900) + self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False) + txs_sent += self.txs_sent(file=stdout) # process and graph the output data = [self.load_data('client_%s.log' % i) for i in self.clients] @@ -53,11 +56,11 @@ def execute(self): branch = GnuplotHelper.buildInfo().branch duration = last - first - average = float(len(self.clients)*self.ITERATIONS) / float(duration) if duration != 0 else 0 + average = float(txs_sent) / float(duration) if duration != 0 else 0 date = datetime.now().strftime("%Y/%m/%d %H:%M:%S") GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'), branch, date, - str(self.mode), str(len(self.clients)*self.ITERATIONS), str(duration), '%.3f' % average) + str(self.mode), str(txs_sent), str(duration), '%.3f' % average) # persist the result self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average) @@ -104,4 +107,3 @@ def bin_data(self, first, last, data, binned_data): for _, t in data: b[t] = 1 if t not in b else b[t] + 1 for t in range(first, last+1): binned_data[t-first] = 0 if t not in b else b[t] return binned_data - diff --git a/tests/ten/ten_per_003/Input/client.py b/tests/ten/ten_per_003/Input/client.py index 9e6f84d0..05a9b66a 100644 --- a/tests/ten/ten_per_003/Input/client.py +++ b/tests/ten/ten_per_003/Input/client.py @@ -39,17 +39,16 @@ def run(name, chainId, web3, sending_accounts, num_accounts, num_iterations, amo txs.append((tx, i)) logging.info('Bulk sending transactions to the network') - stats = [0,0] receipts = [] start_time = time.perf_counter() for tx in txs: try: receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1])) - stats[0] += 1 - except: - logging.error('Error sending raw transaction, sent = %d', len(receipts)) - stats[1] += 1 - logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats)) + except Exception as e: + logging.error('Error sending raw transaction', e) + logging.warning('Continuing with smaller number of transactions ...') + break + logging.info('Number of transactions sent = %d', len(receipts)) end_time = time.perf_counter() duration = end_time - start_time diff --git a/tests/ten/ten_per_003/run.py b/tests/ten/ten_per_003/run.py index a1e1e345..b2679390 100644 --- a/tests/ten/ten_per_003/run.py +++ b/tests/ten/ten_per_003/run.py @@ -34,9 +34,12 @@ def execute(self): pk_file2, conn2 = self.setup_client('client_two', funds_needed) self.run_client('client_one', pk_file1, conn1) self.run_client('client_two', pk_file2, conn2) + txs_sent = 0 for i in self.clients: - self.waitForGrep(file='client_%s.out' % i, expr='Client client_%s completed' % i, timeout=900) - self.ratio_failures(file=os.path.join(self.output, 'client_%s.out' % i)) + stdout = os.path.join(self.output,'client_%s.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=900) + self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False) + txs_sent += self.txs_sent(file=stdout) # process and graph the output data = [self.load_data('client_%s.log' % i) for i in self.clients] @@ -54,11 +57,11 @@ def execute(self): branch = GnuplotHelper.buildInfo().branch duration = last - first - average = float(len(self.clients) * self.ITERATIONS) / float(duration) if duration != 0 else 0 + average = float(txs_sent) / float(duration) if duration != 0 else 0 date = datetime.now().strftime("%Y/%m/%d %H:%M:%S") GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'), branch, date, - str(self.mode), str(len(self.clients) * self.ITERATIONS), str(duration), '%.3f' % average) + str(self.mode), str(txs_sent), str(duration), '%.3f' % average) # persist the result self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average) diff --git a/tests/ten/ten_per_004/Input/client.py b/tests/ten/ten_per_004/Input/client.py index f55a1e2b..12537109 100644 --- a/tests/ten/ten_per_004/Input/client.py +++ b/tests/ten/ten_per_004/Input/client.py @@ -30,16 +30,15 @@ def run(name, chainId, web3, account, num_accounts, num_iterations, amount, gas_ txs.append((tx, i)) logging.info('Bulk sending transactions to the network') - stats = [0,0] receipts = [] for tx in txs: try: receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1])) - stats[0] += 1 - except: - logging.error('Error sending raw transaction, sent = %d', len(receipts)) - stats[1] += 1 - logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats)) + except Exception as e: + logging.error('Error sending raw transaction', e) + logging.warning('Continuing with smaller number of transactions ...') + break + logging.info('Number of transactions sent = %d', len(receipts)) logging.info('Waiting for last transaction') web3.eth.wait_for_transaction_receipt(receipts[-1][0], timeout=600) diff --git a/tests/ten/ten_per_004/run.py b/tests/ten/ten_per_004/run.py index 6c3fa649..782be672 100644 --- a/tests/ten/ten_per_004/run.py +++ b/tests/ten/ten_per_004/run.py @@ -1,7 +1,7 @@ import os, time from datetime import datetime from collections import OrderedDict -from pysys.constants import PASSED, FAILED +from pysys.constants import PASSED from ten.test.basetest import TenNetworkTest from ten.test.utils.gnuplot import GnuplotHelper @@ -31,9 +31,12 @@ def execute(self): # run the clients setup = [self.setup_client('client_%d' % i, funds_needed) for i in range(self.CLIENTS)] for i in range(self.CLIENTS): self.run_client('client_%d' % i, setup[i][0], setup[i][1]) + txs_sent = 0 for i in range(self.CLIENTS): - self.waitForGrep(file='client_%d.out' % i, expr='Client client_%d completed' % i, timeout=900) - self.ratio_failures(file=os.path.join(self.output, 'client_%d.out' % i)) + stdout = os.path.join(self.output,'client_%d.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%d completed' % i, timeout=900) + self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False) + txs_sent += self.txs_sent(file=stdout) # process and graph the output data = [self.load_data('client_%d.log' % i) for i in range(self.CLIENTS)] @@ -59,7 +62,7 @@ def execute(self): date = datetime.now().strftime("%Y/%m/%d %H:%M:%S") GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'), branch, date, - str(self.mode), str(self.CLIENTS*self.ITERATIONS), str(duration), '%d' % self.CLIENTS) + str(self.mode), str(txs_sent), str(duration), '%d' % self.CLIENTS) # persist the result self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average) diff --git a/tests/ten/ten_per_005/Input/storage_client.py b/tests/ten/ten_per_005/Input/storage_client.py index 0dd93e34..c6d15724 100644 --- a/tests/ten/ten_per_005/Input/storage_client.py +++ b/tests/ten/ten_per_005/Input/storage_client.py @@ -41,12 +41,11 @@ def run(name, chainId, web3, account, contract, num_iterations, gas_limit): for tx in txs: try: receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1])) - stats[0] += 1 except Exception as e: - logging.error('Error sending raw transaction, sent = %d', len(receipts)) - logging.error('Exception is', e) - stats[1] += 1 - logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats)) + logging.error('Error sending raw transaction', e) + logging.warning('Continuing with smaller number of transactions ...') + break + logging.info('Number of transactions sent = %d', len(receipts)) for receipt in tenths(receipts): logging.info('Waiting for transaction receipt number %s', receipt[1]) diff --git a/tests/ten/ten_per_005/run.py b/tests/ten/ten_per_005/run.py index 7503ab1a..0a5288a7 100644 --- a/tests/ten/ten_per_005/run.py +++ b/tests/ten/ten_per_005/run.py @@ -33,9 +33,12 @@ def execute(self): # run the clients setup = [self.setup_client('client_%d' % i, funds_needed) for i in range(self.CLIENTS)] for i in range(self.CLIENTS): self.run_client('client_%d' % i, storage, setup[i][0], setup[i][1]) + txs_sent = 0 for i in range(self.CLIENTS): - self.waitForGrep(file='client_%d.out' % i, expr='Client client_%d completed' % i, timeout=900) - self.ratio_failures(file=os.path.join(self.output, 'client_%d.out' % i)) + stdout = os.path.join(self.output,'client_%d.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%d completed' % i, timeout=900) + self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False) + txs_sent += self.txs_sent(file=stdout) # process and graph the output data = [self.load_data('client_%d.log' % i) for i in range(self.CLIENTS)] @@ -61,7 +64,7 @@ def execute(self): date = datetime.now().strftime("%Y/%m/%d %H:%M:%S") GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'), branch, date, - str(self.mode), str(self.CLIENTS * self.ITERATIONS), str(duration), '%d' % self.CLIENTS) + str(self.mode), str(txs_sent), str(duration), '%d' % self.CLIENTS) # persist the result self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average) diff --git a/tests/ten/ten_per_006/Input/client.py b/tests/ten/ten_per_006/Input/client.py index c94fdb17..5005bfd2 100644 --- a/tests/ten/ten_per_006/Input/client.py +++ b/tests/ten/ten_per_006/Input/client.py @@ -34,29 +34,25 @@ def run(name, chainId, web3, account, num_accounts, num_iterations, amount, gas_ logging.info('Bulk sending transactions to the network') receipts = [] - stats = [0,0] for tx in txs: try: receipt = web3.eth.send_raw_transaction(tx[0].rawTransaction) receipts.append((receipt, tx[1])) logging.info('Sent %d', tx[1]) - stats[0] += 1 except Exception as e: - logging.info('Error sending raw transaction, sent = %d', len(receipts)) - logging.error(e) - stats[1] += 1 + logging.error('Error sending raw transaction', e) + logging.warning('Continuing with smaller number of transactions ...') + break + logging.info('Number of transactions sent = %d', len(receipts)) logging.info('Waiting for transactions') for receipt in receipts: try: web3.eth.wait_for_transaction_receipt(receipt[0], timeout=30) logging.info('Received tx receipt for %d' % receipt[1]) - stats[0] += 1 except Exception as e: logging.error('Timedout waiting for %d' % receipt[1]) logging.error(e) - stats[1] += 1 - logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats)) logging.info('Logging the timestamps of each transaction') with open('%s_throughput.log' % name, 'w') as fp: diff --git a/tests/ten/ten_per_006/run.py b/tests/ten/ten_per_006/run.py index 0a29497b..db2245d1 100644 --- a/tests/ten/ten_per_006/run.py +++ b/tests/ten/ten_per_006/run.py @@ -2,7 +2,7 @@ import numpy as np from datetime import datetime from collections import OrderedDict -from pysys.constants import PASSED, FAILED +from pysys.constants import PASSED from ten.test.basetest import TenNetworkTest from ten.test.utils.gnuplot import GnuplotHelper @@ -36,6 +36,7 @@ def execute(self): scale = scale + increment # run the clients and wait for their completion + txs_sent = 0 results_file = os.path.join(self.output, 'results.log') with open(results_file, 'w') as fp: for clients in [2,3,4]: @@ -50,12 +51,13 @@ def execute(self): start_ns = time.perf_counter_ns() with open(signal, 'w') as sig: sig.write('go') for i in range(0, clients): - self.waitForGrep(file=os.path.join(out_dir, 'client_%s.out' % i), - expr='Client client_%s completed' % i, timeout=300) - self.ratio_failures(file=os.path.join(out_dir, 'client_%s.out' % i)) + stdout = os.path.join(out_dir, 'client_%s.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=300) + self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False) + txs_sent += self.txs_sent(file=stdout) end_ns = time.perf_counter_ns() - bulk_throughput = float(clients * self.ITERATIONS) / float((end_ns - start_ns) / 1e9) + bulk_throughput = float(txs_sent) / float((end_ns - start_ns) / 1e9) throughput = self.process_throughput(clients, out_dir) self.log.info('Bulk rate throughput %.2f (requests/sec)' % bulk_throughput) self.log.info('Approx. throughput %.2f (requests/sec)' % throughput) @@ -152,4 +154,3 @@ def find_overlap(self, lists): overlap = np.array(lists[0]) for l in lists[1:]: overlap = np.intersect1d(overlap, np.array(l)) return overlap.tolist()[0], overlap.tolist()[-1] - diff --git a/tests/ten/ten_per_010/run.py b/tests/ten/ten_per_010/run.py index 087cb8dd..2607406e 100644 --- a/tests/ten/ten_per_010/run.py +++ b/tests/ten/ten_per_010/run.py @@ -30,13 +30,13 @@ def execute(self): with open(signal, 'w') as sig: sig.write('go') for i in range(0, clients): - self.waitForGrep(file=os.path.join(out_dir, 'client_%s.out' % i), - expr='Client client_%s completed' % i, timeout=300) - self.ratio_failures(file=os.path.join(out_dir, 'client_%s.out' % i)) + stdout = os.path.join(out_dir, 'client_%s.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=300) + self.ratio_failures(file=stdout) end_ns = time.perf_counter_ns() - bulk_throughput = float(clients * self.ITERATIONS) / float((end_ns-start_ns)/1e9) - avg_latency, mode_latency = self.process_latency(clients, out_dir) + num_data, avg_latency, mode_latency = self.process_latency(clients, out_dir) + bulk_throughput = float(num_data) / float((end_ns-start_ns)/1e9) throughput = self.process_throughput(clients, out_dir, start_ns, end_ns) self.log.info('Bulk rate throughput %.2f (requests/sec)' % bulk_throughput) self.log.info('Approx. throughput %.2f (requests/sec)' % throughput) @@ -85,7 +85,8 @@ def process_latency(self, num_clients, out_dir): with open(os.path.join(out_dir, 'client_%s_latency.log' % i), 'r') as fp: for line in fp.readlines(): data.append(float(line.strip())) data.sort() - avg_latency = (sum(data) / len(data)) + num_data = len(data) + avg_latency = (sum(data) / num_data) bins = self.bin_array(data) max_value = 0 @@ -97,7 +98,7 @@ def process_latency(self, num_clients, out_dir): mode_latency = b fp.write('%.2f %d\n' % (b, v)) fp.flush() - return avg_latency, mode_latency + return num_data, avg_latency, mode_latency def process_throughput(self, num_clients, out_dir, start, end): client_bins = [] # bins for a given client diff --git a/tests/ten/ten_per_011/run.py b/tests/ten/ten_per_011/run.py index c363adb7..b250dd73 100644 --- a/tests/ten/ten_per_011/run.py +++ b/tests/ten/ten_per_011/run.py @@ -45,16 +45,16 @@ def execute(self): with open(signal, 'w') as sig: sig.write('go') for i in range(0, clients): - self.waitForGrep(file=os.path.join(out_dir, 'client_%s.out' % i), - expr='Client client_%s completed' % i, timeout=300) - self.ratio_failures(file=os.path.join(out_dir, 'client_%s.out' % i)) + stdout = os.path.join(out_dir, 'client_%s.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=300) + self.ratio_failures(file=stdout) # stop transacting to set the storage value hprocess.stop() end_ns = time.perf_counter_ns() - bulk_throughput = float(clients * self.ITERATIONS) / float((end_ns - start_ns) / 1e9) - avg_latency, mode_latency, nnth_percentile = self.process_latency(clients, out_dir) + num_data, avg_latency, mode_latency, nnth_percentile = self.process_latency(clients, out_dir) + bulk_throughput = float(num_data) / float((end_ns - start_ns) / 1e9) throughput = self.process_throughput(clients, out_dir, start_ns, end_ns) self.log.info('Bulk rate throughput %.2f (requests/sec)' % bulk_throughput) self.log.info('Approx. throughput %.2f (requests/sec)' % throughput) @@ -126,7 +126,8 @@ def process_latency(self, num_clients, out_dir): with open(os.path.join(out_dir, 'client_%s_latency.log' % i), 'r') as fp: for line in fp.readlines(): data.append(float(line.strip())) data.sort() - avg_latency = (sum(data) / len(data)) + num_data = len(data) + avg_latency = (sum(data) / num_data) nnth_percentile = np.percentile(data, 99) bins = self.bin_array(data) @@ -139,7 +140,7 @@ def process_latency(self, num_clients, out_dir): mode_latency = b fp.write('%.2f %d\n' % (b, v)) fp.flush() - return avg_latency, mode_latency, nnth_percentile + return num_data, avg_latency, mode_latency, nnth_percentile def process_throughput(self, num_clients, out_dir, start, end): client_bins = [] # bins for a given client diff --git a/tests/ten/ten_per_012/run.py b/tests/ten/ten_per_012/run.py index bf219df7..52f5ba45 100644 --- a/tests/ten/ten_per_012/run.py +++ b/tests/ten/ten_per_012/run.py @@ -45,16 +45,16 @@ def execute(self): with open(signal, 'w') as sig: sig.write('go') for i in range(0, clients): - self.waitForGrep(file=os.path.join(out_dir, 'client_%s.out' % i), - expr='Client client_%s completed' % i, timeout=600) - self.ratio_failures(file=os.path.join(out_dir, 'client_%s.out' % i)) + stdout = os.path.join(out_dir, 'client_%s.out' % i) + self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=600) + self.ratio_failures(file=stdout) # stop transacting to set the storage value hprocess.stop() end_ns = time.perf_counter_ns() - bulk_throughput = float(clients * self.ITERATIONS) / float((end_ns - start_ns) / 1e9) - avg_latency, mode_latency, nnth_percentile = self.process_latency(clients, out_dir) + num_data, avg_latency, mode_latency, nnth_percentile = self.process_latency(clients, out_dir) + bulk_throughput = float(num_data) / float((end_ns - start_ns) / 1e9) throughput = self.process_throughput(clients, out_dir, start_ns, end_ns) self.log.info('Bulk rate throughput %.2f (requests/sec)' % bulk_throughput) self.log.info('Approx. throughput %.2f (requests/sec)' % throughput) @@ -126,7 +126,8 @@ def process_latency(self, num_clients, out_dir): with open(os.path.join(out_dir, 'client_%s_latency.log' % i), 'r') as fp: for line in fp.readlines(): data.append(float(line.strip())) data.sort() - avg_latency = (sum(data) / len(data)) + num_data = len(data) + avg_latency = (sum(data) / num_data) nnth_percentile = np.percentile(data, 99) bins = self.bin_array(data) @@ -139,7 +140,7 @@ def process_latency(self, num_clients, out_dir): mode_latency = b fp.write('%.2f %d\n' % (b, v)) fp.flush() - return avg_latency, mode_latency, nnth_percentile + return num_data, avg_latency, mode_latency, nnth_percentile def process_throughput(self, num_clients, out_dir, start, end): client_bins = [] # bins for a given client