Added command execution time measurement

  This will be useful to keep track of possible performance degradation when code changes.

Author: MakSl

testgres/performance_test.py

@@ -0,0 +1,33 @@
+from .plugins.pg_probackup2.pg_probackup2.tests.basic_test import ProbackupTest
+
+class PerformanceTest(ProbackupTest):
+
+    def test_full_backup_perf_basic(self):
+        """
+        Full backup in 4 threads should be faster than in 1 thread
+        """
+        node = self.pg_node.make_simple('node', pg_options={"fsync": "off", "synchronous_commit": "off"})
+
+        self.pb.init()
+        self.pb.add_instance('node', node)
+        self.pb.set_archiving('node', node)
+        node.slow_start()
+
+        # Fill with data
+        node.pgbench_init(scale=100, no_vacuum=True)
+
+        # FULL
+        backup_id_1t = self.pb.backup_node('node', node, options=["--no-validate"], check_time=True)
+        elapsed_time_1t = backup_id_1t.execution_time
+        # Full in 4 threads
+        backup_id_4t = self.pb.backup_node('node', node, options=["-j", "4", "--no-validate"], check_time=True)
+        elapsed_time_4t = backup_id_4t.execution_time
+
+        # Full by basebackup
+        backup = node.backup(check_time=True)
+        elapsed_time_base = backup.elapsed_time
+
+        print(f"elapsed_time_1t: {elapsed_time_1t}, elapsed_time_4t: {elapsed_time_4t}, elapsed_time_base: {elapsed_time_base}")
+        self.assertLess(elapsed_time_4t, elapsed_time_base, "Full backup in 4 threads should be faster than pg_basebackup")
+        self.assertLess(elapsed_time_4t, elapsed_time_1t, "Full backup in 4 threads should be faster than in 1 thread")
+        self.assertLess(elapsed_time_1t, elapsed_time_base, "Full backup should be faster than pg_basebackup")

testgres/plugins/pg_probackup2/pg_probackup2/app.py

@@ -43,7 +43,7 @@ def __str__(self):
 class ProbackupApp:
 
     def __init__(self, test_class: unittest.TestCase,
-                 pg_node, pb_log_path, test_env, auto_compress_alg, backup_dir):
+                 pg_node, pb_log_path, test_env, auto_compress_alg, backup_dir, execution_time):
         self.test_class = test_class
         self.pg_node = pg_node
         self.pb_log_path = pb_log_path
@@ -56,9 +56,10 @@ def __init__(self, test_class: unittest.TestCase,
         self.verbose = init_params.verbose
         self.archive_compress = init_params.archive_compress
         self.test_class.output = None
+        self.execution_time = execution_time
 
     def run(self, command, gdb=False, old_binary=False, return_id=True, env=None,
-            skip_log_directory=False, expect_error=False, use_backup_dir=True):
+            skip_log_directory=False, expect_error=False, use_backup_dir=True, execution_time=False):
         """
         Run pg_probackup
         backup_dir: target directory for making backup
@@ -113,11 +114,22 @@ def run(self, command, gdb=False, old_binary=False, return_id=True, env=None,
                 cmdline = ['gdbserver'] + ['localhost:' + str(gdb_port)] + cmdline
                 print("pg_probackup gdb suspended, waiting gdb connection on localhost:{0}".format(gdb_port))
 
-            self.test_class.output = subprocess.check_output(
-                cmdline,
-                stderr=subprocess.STDOUT,
-                env=env
-            ).decode('utf-8', errors='replace')
+            if execution_time:
+                start_time = time.time()
+                self.test_class.output = subprocess.check_output(
+                    cmdline,
+                    stderr=subprocess.STDOUT,
+                    env=env
+                ).decode('utf-8', errors='replace')
+                end_time = time.time()
+                self.execution_time = end_time - start_time
+            else:
+                self.test_class.output = subprocess.check_output(
+                    cmdline,
+                    stderr=subprocess.STDOUT,
+                    env=env
+                ).decode('utf-8', errors='replace')
+
             if command[0] == 'backup' and return_id:
                 # return backup ID
                 for line in self.test_class.output.splitlines():
@@ -213,7 +225,8 @@ def backup_node(
             old_binary=False, return_id=True, no_remote=False,
             env=None,
             expect_error=False,
-            sync=False
+            sync=False,
+            execution_time=False
     ):
         if options is None:
             options = []
@@ -253,7 +266,7 @@ def backup_node(
             cmd_list += ['--no-sync']
 
         return self.run(cmd_list + options, gdb, old_binary, return_id, env=env,
-                        expect_error=expect_error)
+                        expect_error=expect_error, execution_time=execution_time)
 
     def backup_replica_node(self, instance, node, data_dir=False, *,
                             master, backup_type='full', datname=False,