postgresql_query: return a list containing execution time per query in milliseconds (ansible-collections#792)

Author: Andersson007

changelogs/fragments/0-postgresql_query.yml

@@ -0,0 +1,2 @@
+minor_changes:
+- postgresql_query - returns the `execution_time_ms` list containing execution time per query in milliseconds (https://github.com/ansible-collections/community.postgresql/issues/787).

plugins/modules/postgresql_query.py

@@ -249,9 +249,19 @@
     returned: changed
     type: int
     sample: 5
+execution_time_ms:
+    description:
+    - A list containing execution time per query in milliseconds.
+    - The measurements are done right before and after passing
+      the query to the driver for execution.
+    returned: success
+    type: list
+    sample: [7104]
+    version_added: '3.10.0'
 '''
 
 import re
+import time
 
 from ansible.module_utils._text import to_native
 from ansible.module_utils.basic import AnsibleModule
@@ -285,6 +295,18 @@
 #
 
 
+def execute_and_return_time(cursor, query, args):
+    # Measure query execution time in milliseconds as requested in
+    # https://github.com/ansible-collections/community.postgresql/issues/787
+    start_time = time.perf_counter()
+
+    cursor.execute(query, args)
+
+    # Calculate the execution time rounding it to 4 decimal places
+    exec_time_ms = round((time.perf_counter() - start_time) * 1000, 4)
+    return cursor, exec_time_ms
+
+
 def insane_query(string):
     for c in string:
         if c not in (' ', '\n', '', '\t'):
@@ -367,14 +389,19 @@ def main():
     changed = False
 
     query_all_results = []
+    execution_time_ms = []
     rowcount = 0
     statusmessage = ''
 
     # Execute query:
     for query in query_list:
         try:
             current_query_txt = cursor.mogrify(query, args)
-            cursor.execute(query, args)
+
+            cursor, exec_time_ms = execute_and_return_time(cursor, query, args)
+
+            execution_time_ms.append(exec_time_ms)
+
             statusmessage = cursor.statusmessage
             if cursor.rowcount > 0:
                 rowcount += cursor.rowcount
@@ -444,6 +471,7 @@ def main():
         query_result=query_result,
         query_all_results=query_all_results,
         rowcount=rowcount,
+        execution_time_ms=execution_time_ms,
     )
 
     cursor.close()

tests/integration/targets/postgresql_query/tasks/postgresql_query_initial.yml

@@ -43,6 +43,7 @@
       - result.statusmessage == 'ANALYZE'
       - result.query_result == {}
       - result.query_all_results == [{}]
+      - result.execution_time_ms[0] > 0
 
   - name: postgresql_query - simple select query to test_table
     become_user: '{{ pg_user }}'
@@ -524,6 +525,7 @@
   - assert:
       that:
       - result.rowcount == 1
+      - result.execution_time_ms[0] > 0
 
   #############################################################################
   # Issue https://github.com/ansible-collections/community.postgresql/issues/47
@@ -575,6 +577,9 @@
       - result.rowcount == 3
       - result.query_result == [{"?column?": 1}]
       - 'result.query_all_results == [[{"?column?": 1}], [{"?column?": 1}], [{"?column?": 1}]]'
+      - result.execution_time_ms[0] > 0
+      - result.execution_time_ms[1] > 0
+      - result.execution_time_ms[2] > 0
 
   - name: Run SHOW query
     become_user: '{{ pg_user }}'
@@ -586,4 +591,4 @@
 
   - assert:
       that:
-      - result is not changed
+      - result is not changed