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.

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

Add profile block and profiling of import_* jinja calls #57850

Merged
merged 4 commits into from
Oct 5, 2020

Conversation

jfindlay
Copy link
Contributor

@jfindlay jfindlay commented Jul 1, 2020

Originally from @ferringb.

What does this PR do?

Add the profile jinja block to enable profiling of individual lines or blocks within sls files and enable the same profile mechanism for import_yaml, import_json, import_text.

What issues does this PR fix or reference?

Fixes: #57849

Motivation

When working with a very large codebase, it becomes more important to trace inefficiencies with state and pillar render times. The profile jinja block enables the user to get finely detailed information on the most expensive areas in the codebase.

Example

Setup

# tree /srv/salt/
/srv/salt/
├── data.sls
└── example.sls

0 directories, 2 files
# cat /srv/salt/data.sls 
{%- profile as 'render import' %}
  {%- profile as 'compute imported data' %}
    {%- set values = {'counter': 0} %}
    {%- for i in range(524288) %}
      {%- do values.update({'counter': i}) %}
    {%- endfor %}
  {%- endprofile %}

  {%- profile as 'define imported data' %}
data: {{ values['counter'] }}
  {%- endprofile %}
{%- endprofile %}
# cat /srv/salt/example.sls 
{%- import_yaml 'data.sls' as imported %}

{%- profile as 'local data' %}
  {%- set local_data = {'counter': 0} %}
  {%- for i in range(313377) %}
    {%- do local_data.update({'counter': i}) %}
  {%- endfor %}
{%- endprofile %}

test:
  cmd.run:
    - name: |-
        printf 'local data: %s\nimported data: %s' '{{ local_data['counter'] }}' '{{ imported['data'] }}'

Output

The ***asterisked lines*** below are new and correspond to the profile blocks in the code above.

# salt-call --local -l profile state.apply example
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[INFO    ] Loading fresh modules for state activity
***[PROFILE ] Time (in seconds) to render profile block 'compute imported data': 1.5444426536560059***
***[PROFILE ] Time (in seconds) to render profile block 'define imported data': 1.52587890625e-05***
***[PROFILE ] Time (in seconds) to render profile block 'render import': 1.5447514057159424***
***[PROFILE ] Time (in seconds) to render import_yaml 'data.sls': 1.5500736236572266***
***[PROFILE ] Time (in seconds) to render profile block 'local data': 0.9385035037994385***
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/example.sls' using 'jinja' renderer: 2.5143165588378906
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/example.sls' using 'yaml' renderer: 0.0009343624114990234
[INFO    ] Running state [printf 'local data: %s\nimported data: %s' '313376' '524287'] at time 07:35:09.840141
[INFO    ] Executing state cmd.run for [printf 'local data: %s\nimported data: %s' '313376' '524287']
[INFO    ] Executing command 'printf 'local data: %s\nimported data: %s' '313376' '524287'' in directory '/root'
[INFO    ] {'stderr': '', 'pid': 285, 'stdout': 'local data: 313376\nimported data: 524287', 'retcode': 0}
[INFO    ] Completed state [printf 'local data: %s\nimported data: %s' '313376' '524287'] at time 07:35:09.846389 (duration_in_ms=6.249)
local:
----------
          ID: test
    Function: cmd.run
        Name: printf 'local data: %s\nimported data: %s' '313376' '524287'
      Result: True
     Comment: Command "printf 'local data: %s\nimported data: %s' '313376' '524287'" run
     Started: 07:35:09.840140
    Duration: 6.249 ms
     Changes:   
              ----------
              pid:
                  285
              retcode:
                  0
              stderr:
              stdout:
                  local data: 313376
                  imported data: 524287

Summary for local
------------
Succeeded: 1 (changed=1)
Failed:    0
------------
Total states run:     1
Total run time:   6.249 ms

Merge requirements satisfied?

[NOTICE] Bug fixes or features added to Salt require tests.

Commits signed with GPG?

Yes

@jfindlay jfindlay requested a review from a team as a code owner July 1, 2020 08:27
@ghost ghost requested review from xeacott and removed request for a team July 1, 2020 08:27
@jfindlay jfindlay force-pushed the jfindlay/jinja-profile branch 4 times, most recently from 41a24b0 to 757daa5 Compare July 1, 2020 18:42
@jfindlay jfindlay force-pushed the jfindlay/jinja-profile branch from 757daa5 to b88e2f8 Compare July 1, 2020 19:50
@sagetherage sagetherage requested review from cmcmarrow and dwoz July 22, 2020 22:42
@sagetherage sagetherage added Feature new functionality including changes to functionality and code refactors, etc. Magnesium Mg release after Na prior to Al labels Jul 22, 2020
cmcmarrow
cmcmarrow previously approved these changes Aug 6, 2020
Copy link
Contributor

@cmcmarrow cmcmarrow left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good thanks for the PR!

For some of the more complex salt code--or when salt functions lack
timing stats themselves--it's desirable to be able to do thus:
```sls
{%- profile as 'inner test' %}
< jinja-code >
{%- endprofile %}
```
And get a log line like thus:
```
2019-08-05 22:10:59,531 [salt.utils.jinja ][PROFILE ][26803] Time (in seconds) to render profile block 'inner test': 5.96046447754e-06
```

This commit adds a new `profile` block tag that emits these log
statements.

The same machinery used to support the `profile` block tag is also wired
into `import_*` blocks.  For example:
```sls
{%- import grains.sls as 'blah' %}
```
results in the following log statement:
```
2019-08-05 22:10:59,542 [salt.utils.jinja ][PROFILE ][26803] Time (in seconds) to render import_yaml 'grains.sls': 0.0106961727142
```
@jfindlay
Copy link
Contributor Author

The pre-commit errors are not from my changes. It looks like you've enforced CI style checks before refactoring the codebase.

@dwoz dwoz merged commit f79cc35 into saltstack:master Oct 5, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Feature new functionality including changes to functionality and code refactors, etc. has-failing-test Magnesium Mg release after Na prior to Al
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[FEATURE REQUEST] Add ability to profile jinja code
5 participants