Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

profile_tasks miscalculates task run time with serial execution #83

Closed
Akasurde opened this issue Aug 15, 2020 · 0 comments · Fixed by #263
Closed

profile_tasks miscalculates task run time with serial execution #83

Akasurde opened this issue Aug 15, 2020 · 0 comments · Fixed by #263
Assignees
@saito-hideki
Labels
bug This issue/PR relates to a bug.

Comments

@Akasurde
Copy link
Member

From @timurakhmadeev on Aug 15, 2020 13:07

SUMMARY

The callback plugin shows time of the last task run. When a task is run in bathes via 'serial', it leads to incorrect results.

ISSUE TYPE
  • Bug Report
COMPONENT NAME

profile_tasks

ANSIBLE VERSION
  config file = /home/tiak/test/ansible.cfg
  configured module search path = [u'/home/tiak/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/dist-packages/ansible
  executable location = /usr/bin/ansible
  python version = 2.7.17 (default, Jul 20 2020, 15:37:01) [GCC 7.5.0]
CONFIGURATION
DEFAULT_CALLBACK_WHITELIST(/home/tiak/test/ansible.cfg) = [u'profile_tasks']
INTERPRETER_PYTHON(/home/tiak/test/ansible.cfg) = auto_silent
OS / ENVIRONMENT

Ubuntu 18.04

STEPS TO REPRODUCE
$ cat inv.yml 
all:
  hosts:
    host1:
      ansible_host: localhost
    host2:
      ansible_host: localhost

$ cat test.yml 
- hosts: all
  connection: local
  serial: 1
  gather_facts: no
  tasks:
    - name: sleep 3s
      shell: sleep 3
EXPECTED RESULTS

Total time reported by profile_tasks is 6s+

ACTUAL RESULTS

Total time reported by profile_tasks is ~3s

$ time ansible-playbook -i inv.yml test.yml 

PLAY [all] ****************************************************************************************************************************************************

TASK [sleep 3s] ***********************************************************************************************************************************************
Saturday 15 August 2020  16:05:30 +0300 (0:00:00.035)       0:00:00.035 ******* 
changed: [host2]

PLAY [all] ****************************************************************************************************************************************************

TASK [sleep 3s] ***********************************************************************************************************************************************
Saturday 15 August 2020  16:05:34 +0300 (0:00:03.677)       0:00:03.713 ******* 
changed: [host1]

PLAY RECAP ****************************************************************************************************************************************************
host1                      : ok=1    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   
host2                      : ok=1    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   

Saturday 15 August 2020  16:05:37 +0300 (0:00:03.446)       0:00:07.159 ******* 
=============================================================================== 
sleep 3s ----------------------------------------------------------------------------------------------------------------------------------------------- 3.45s

real	0m7.907s
user	0m1.664s
sys	0m0.507s

Copied from original issue: ansible/ansible#71293
@Akasurde Akasurde mentioned this issue Aug 15, 2020
Closed
@maxamillion maxamillion added the bug This issue/PR relates to a bug. label Sep 25, 2020
@saito-hideki saito-hideki mentioned this issue Sep 10, 2021
Merged
@saito-hideki saito-hideki self-assigned this Sep 10, 2021
ansible-zuul bot added a commit that referenced this issue Sep 21, 2021
@ansible-zuul
Merge pull request #263 from saito-hideki/issue/83
96c342f 
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 <[email protected]>
Reviewed-by: None <None>
@bot-ross bot-ross bot mentioned this issue May 23, 2022
Merged
1 task
@midnight-bot-6658 midnight-bot-6658 bot mentioned this issue May 23, 2022
Merged
1 task
@negative-7-bot negative-7-bot bot mentioned this issue May 23, 2022
Merged
1 task
@renovate renovate bot mentioned this issue May 23, 2022
Merged
1 task
@lumiere-bot lumiere-bot bot mentioned this issue May 23, 2022
Merged
1 task
@stimpy-bot stimpy-bot bot mentioned this issue May 23, 2022
Merged
1 task
@wyoa-bot wyoa-bot bot mentioned this issue May 23, 2022
Merged
1 task
This was referenced May 23, 2022
Merged
Merged
Merged
@ghost ghost mentioned this issue May 23, 2022
Merged
1 task
@renovate renovate bot mentioned this issue May 23, 2022
Merged
1 task
@iudicael-bot iudicael-bot bot mentioned this issue May 23, 2022
Merged
1 task
@bloopy-boi bloopy-boi bot mentioned this issue May 23, 2022
Merged
1 task
This was referenced May 23, 2022
Open
Closed
Closed
Merged
Merged
Merged
Merged
Merged
Merged
Merged
@aki-bot aki-bot bot mentioned this issue May 28, 2022
Merged
1 task
This was referenced May 28, 2022
Closed
Merged
Open
Merged
Open
Merged
Merged
Closed
Merged
Closed
Merged
Merged
This was referenced Jun 4, 2022
Merged
Merged
Closed
Merged
This was referenced Jun 18, 2022
Closed
Closed
This was referenced Jul 31, 2022
Closed
Merged
This was referenced Aug 17, 2022
Merged
Closed
Closed
This was referenced Sep 14, 2022
Closed
Closed
@trux-bot trux-bot bot mentioned this issue Sep 16, 2022
Merged
1 task
@snoopy82481-bot snoopy82481-bot bot mentioned this issue Sep 21, 2022
Closed
1 task
@renovate renovate bot mentioned this issue Oct 2, 2022
Merged
1 task
@renovate-tests renovate-tests mentioned this issue Nov 24, 2022
Open
1 task
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@saito-hideki saito-hideki

Labels
bug This issue/PR relates to a bug.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

profile_tasks - Correctly calculate task execution time with serial execution
3 participants
@Akasurde @maxamillion @saito-hideki