Merge pull request #263 from saito-hideki/issue/83

profile_tasks - Correctly calculate task execution time with serial execution

SUMMARY
Correctly calculate task execution time with serial execution

Fixes #83

ISSUE TYPE

Bugfix Pull Request

COMPONENT NAME

ansible.posix.profile_tasks

ADDITIONAL INFORMATION
After applying this PR, I can confirm that the task execution time with serial execution is correct:

Test playbook:

---
- hosts: issue_83
  gather_facts: false
  connection: local
  serial: 1

  tasks:
    - name: TASK_A
      shell: sleep 3
    - name: TASK_B
      shell: sleep 5
    - name: TASK_C
      shell: sleep 1

Results:

$ ansible-playbook -i inventory playbook/profile_tasks/issue_83.yml 
[DEPRECATION WARNING]: [defaults]callback_whitelist option, normalizing names 
to new standard, use callback_enabled instead. This feature will be removed 
from ansible-core in version 2.15. Deprecation warnings can be disabled by 
setting deprecation_warnings=False in ansible.cfg.

PLAY [issue_83] ****************************************************************

TASK [TASK_A] ******************************************************************
Friday 10 September 2021  12:40:58 +0900 (0:00:00.008)       0:00:00.008 ****** 
changed: [server100]

TASK [TASK_B] ******************************************************************
Friday 10 September 2021  12:41:02 +0900 (0:00:03.210)       0:00:03.219 ****** 
changed: [server100]

TASK [TASK_C] ******************************************************************
Friday 10 September 2021  12:41:07 +0900 (0:00:05.173)       0:00:08.392 ****** 
changed: [server100]

PLAY [issue_83] ****************************************************************

TASK [TASK_A] ******************************************************************
Friday 10 September 2021  12:41:08 +0900 (0:00:01.146)       0:00:09.539 ****** 
changed: [server101]

TASK [TASK_B] ******************************************************************
Friday 10 September 2021  12:41:11 +0900 (0:00:03.185)       0:00:12.724 ****** 
changed: [server101]

TASK [TASK_C] ******************************************************************
Friday 10 September 2021  12:41:16 +0900 (0:00:05.148)       0:00:17.873 ****** 
changed: [server101]

PLAY [issue_83] ****************************************************************

TASK [TASK_A] ******************************************************************
Friday 10 September 2021  12:41:17 +0900 (0:00:01.176)       0:00:19.050 ****** 
changed: [server102]

TASK [TASK_B] ******************************************************************
Friday 10 September 2021  12:41:21 +0900 (0:00:03.174)       0:00:22.224 ****** 
changed: [server102]

TASK [TASK_C] ******************************************************************
Friday 10 September 2021  12:41:26 +0900 (0:00:05.190)       0:00:27.415 ****** 
changed: [server102]

PLAY RECAP *********************************************************************
server100                  : ok=3    changed=3    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   
server101                  : ok=3    changed=3    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   
server102                  : ok=3    changed=3    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   

Friday 10 September 2021  12:41:27 +0900 (0:00:01.173)       0:00:28.588 ****** 
=============================================================================== 
TASK_B ----------------------------------------------------------------- 15.51s
TASK_A ------------------------------------------------------------------ 9.57s
TASK_C ------------------------------------------------------------------ 3.50s

Reviewed-by: Andrew Klychkov <aaklychkov@mail.ru>
Reviewed-by: None <None>
This commit is contained in:
ansible-zuul[bot] 2021-09-21 01:07:49 +00:00 committed by GitHub
commit 96c342fd67
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
2 changed files with 15 additions and 4 deletions

View file

@ -0,0 +1,3 @@
---
bugfixes:
- profile_tasks - Correctly calculate task execution time with serial execution (https://github.com/ansible-collections/ansible.posix/issues/83).

View file

@ -92,7 +92,8 @@ def filled(msg, fchar="*"):
def timestamp(self):
if self.current is not None:
self.stats[self.current]['time'] = time.time() - self.stats[self.current]['time']
elapsed = time.time() - self.stats[self.current]['started']
self.stats[self.current]['elapsed'] += elapsed
def tasktime():
@ -151,8 +152,15 @@ class CallbackModule(CallbackBase):
timestamp(self)
# Record the start time of the current task
# stats[TASK_UUID]:
# started: Current task start time. This value will be updated each time a task
# with the same UUID is executed when `serial` is specified in a playbook.
# elapsed: Elapsed time since the first serialized task was started
self.current = task._uuid
self.stats[self.current] = {'time': time.time(), 'name': task.get_name()}
if self.current not in self.stats:
self.stats[self.current] = {'started': time.time(), 'elapsed': 0.0, 'name': task.get_name()}
else:
self.stats[self.current]['started'] = time.time()
if self._display.verbosity >= 2:
self.stats[self.current]['path'] = task.get_path()
@ -178,7 +186,7 @@ class CallbackModule(CallbackBase):
if self.sort_order is not None:
results = sorted(
self.stats.items(),
key=lambda x: x[1]['time'],
key=lambda x: x[1]['elapsed'],
reverse=self.sort_order,
)
@ -187,7 +195,7 @@ class CallbackModule(CallbackBase):
# Print the timings
for uuid, result in results:
msg = u"{0:-<{2}}{1:->9}".format(result['name'] + u' ', u' {0:.02f}s'.format(result['time']), self._display.columns - 9)
msg = u"{0:-<{2}}{1:->9}".format(result['name'] + u' ', u' {0:.02f}s'.format(result['elapsed']), self._display.columns - 9)
if 'path' in result:
msg += u"\n{0:-<{1}}".format(result['path'] + u' ', self._display.columns)
self._display.display(msg)