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

top_matches slows down with every match and takes a lot of time with big pillars (slow deepcopy) #61950

Open
uhriap opened this issue Apr 14, 2022 · 1 comment · May be fixed by #64606 or #64607
Open

top_matches slows down with every match and takes a lot of time with big pillars (slow deepcopy) #61950

uhriap opened this issue Apr 14, 2022 · 1 comment · May be fixed by #64606 or #64607
Assignees
@dwoz
Labels
Bug broken, incorrect, or confusing behavior Core relates to code central or existential to Salt Performance Pillar severity-medium 3rd level, incorrect or bad functionality, confusing and lacks a work around
Milestone
Approved

Comments

@uhriap
Copy link

uhriap commented Apr 14, 2022

Description
On top parsing top_matches get confirm_top matcher from LazyLoader which in turn lazyloads other matchers, creating LazyLoader on every match call.
-> top_matches

salt/salt/state.py

Line 3955 in 1568067

def top_matches(self, top):

-> confirm_top

salt/salt/state.py

Line 3974 in 1568067

if self.matchers["confirm_top.confirm_top"](_match, _data, _opts):

-> matchers

salt/salt/matchers/confirm_top.py

Line 24 in 1568067

matchers = salt.loader.matchers(__opts__)

-> create new LazyLoader

salt/salt/loader/__init__.py

Line 392 in 1568067

return LazyLoader(_module_dirs(opts, "matchers"), opts, tag="matchers")

-> LazyLoader calls super slow deepcopy(opts)

salt/salt/loader/lazy.py

Line 247 in 1568067

opts = copy.deepcopy(opts)

In my setup top_matches takes 10+ seconds for some minions. Every deepcopy(opts) in LazyLoader takes about 100ms when all pillars in opts.

Expected behavior
Parse top.sls in milliseconds, instead of tens of seconds.

Run examples
salt-call pillar.items --out yaml is about 2MB in size

added some logging 
diff --git a/salt/loader/lazy.py b/salt/loader/lazy.py
index 48c70d01c0..9244bdccd2 100644
--- a/salt/loader/lazy.py
+++ b/salt/loader/lazy.py
@@ -244,7 +244,12 @@ class LazyLoader(salt.utils.lazy.LazyDict):
                 self.pack[i] = self.pack[i].value()
         if opts is None:
             opts = {}
+
+        import time
+        start = time.time()
         opts = copy.deepcopy(opts)
+        log.warning('deepcopy took %.3f', time.time() - start)
+
         for i in ["pillar", "grains"]:
             if i in opts and isinstance(
                 opts[i], salt.loader.context.NamedLoaderContext
time salt-call state.apply -l warning --state-output=changes --state-verbose=False --master localhost 
local:

Summary for local
-------------
Succeeded: 62
Failed:     0
-------------
Total states run:     62
Total run time:    1.205 s

real    0m26.347s
user    0m17.037s
sys     0m0.904s


# grep -P 'LazyLoaded|took' /var/log/salt/minion
2022-04-14 21:19:47,277 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:47,287 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:47,297 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:47,655 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded zfs.is_supported
2022-04-14 21:19:48,510 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,547 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,578 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,580 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,585 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,587 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,597 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,599 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded jinja.render
2022-04-14 21:19:48,600 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded yaml.render
2022-04-14 21:19:48,602 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,604 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:48,607 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded state.apply
2022-04-14 21:19:48,609 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded direct_call.execute
2022-04-14 21:19:48,610 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grains.get
2022-04-14 21:19:48,613 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded saltutil.is_running
2022-04-14 21:19:48,621 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded config.get
2022-04-14 21:19:48,623 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.001
2022-04-14 21:19:51,231 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.148
2022-04-14 21:19:51,386 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.144
2022-04-14 21:19:51,560 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.147
2022-04-14 21:19:51,683 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.121
2022-04-14 21:19:51,848 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.159
2022-04-14 21:19:51,850 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded jinja.render
2022-04-14 21:19:51,850 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded yaml.render
2022-04-14 21:19:51,966 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.116
2022-04-14 21:19:52,097 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:19:52,118 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded confirm_top.confirm_top
2022-04-14 21:19:52,243 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.125
2022-04-14 21:19:52,245 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded compound_match.match
2022-04-14 21:19:52,426 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.181
2022-04-14 21:19:52,428 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded glob_match.match
2022-04-14 21:19:52,545 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.116
2022-04-14 21:19:52,547 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:54,672 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.160
2022-04-14 21:19:54,677 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:54,827 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.149
2022-04-14 21:19:54,833 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:54,963 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.129
2022-04-14 21:19:54,968 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:55,172 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.203
2022-04-14 21:19:55,177 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:55,301 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.123
2022-04-14 21:19:55,306 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:55,426 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:19:55,430 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:55,546 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.115
2022-04-14 21:19:55,550 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:55,668 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.117
2022-04-14 21:19:55,672 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:55,865 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.192
2022-04-14 21:19:55,870 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:55,989 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.118
2022-04-14 21:19:55,993 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,106 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.112
2022-04-14 21:19:56,110 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,214 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.104
2022-04-14 21:19:56,218 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,322 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.104
2022-04-14 21:19:56,326 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,493 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.166
2022-04-14 21:19:56,497 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,613 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.115
2022-04-14 21:19:56,618 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,739 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.120
2022-04-14 21:19:56,743 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,863 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:19:56,867 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:56,982 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.114
2022-04-14 21:19:56,986 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:57,150 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.163
2022-04-14 21:19:57,154 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:57,258 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.103
2022-04-14 21:19:57,262 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:57,366 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.103
2022-04-14 21:19:57,370 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:57,477 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.106
2022-04-14 21:19:57,481 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:57,583 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.101
2022-04-14 21:19:57,586 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:57,764 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.177
2022-04-14 21:19:57,768 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:57,937 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.123
2022-04-14 21:19:57,941 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:58,056 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.115
2022-04-14 21:19:58,060 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:58,180 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:19:58,185 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:58,313 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.127
2022-04-14 21:19:58,317 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:58,503 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.186
2022-04-14 21:19:58,508 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:58,635 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.127
2022-04-14 21:19:58,640 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:58,767 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.126
2022-04-14 21:19:58,771 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:58,896 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.124
2022-04-14 21:19:58,900 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,022 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.121
2022-04-14 21:19:59,026 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,206 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.179
2022-04-14 21:19:59,211 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,332 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.120
2022-04-14 21:19:59,336 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,456 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:19:59,460 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,577 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.115
2022-04-14 21:19:59,581 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,696 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.115
2022-04-14 21:19:59,700 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,872 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.171
2022-04-14 21:19:59,876 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:19:59,989 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.112
2022-04-14 21:19:59,993 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:00,106 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.112
2022-04-14 21:20:00,111 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:00,225 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.113
2022-04-14 21:20:00,229 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:00,399 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.169
2022-04-14 21:20:00,403 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:00,524 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.120
2022-04-14 21:20:00,529 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:00,653 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.123
2022-04-14 21:20:00,657 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:00,778 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.120
2022-04-14 21:20:00,782 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:00,905 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.122
2022-04-14 21:20:00,909 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:01,097 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.187
2022-04-14 21:20:01,101 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:01,225 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.122
2022-04-14 21:20:01,229 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:01,352 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.122
2022-04-14 21:20:01,356 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:01,471 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.114
2022-04-14 21:20:01,475 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:01,600 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.124
2022-04-14 21:20:01,604 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:01,793 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.188
2022-04-14 21:20:01,798 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:01,916 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.117
2022-04-14 21:20:01,920 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:02,033 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.113
2022-04-14 21:20:02,038 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:02,158 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:20:02,162 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:02,279 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.117
2022-04-14 21:20:02,283 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:02,468 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.184
2022-04-14 21:20:02,473 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:02,600 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.127
2022-04-14 21:20:02,605 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:02,729 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.124
2022-04-14 21:20:02,734 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:02,854 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:20:02,858 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grain_match.match
2022-04-14 21:20:03,016 [salt.state       :3982][WARNING ][53183] Top matches took 10.898440
2022-04-14 21:20:03,020 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded saltutil.sync_all
2022-04-14 21:20:03,130 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.110
2022-04-14 21:20:03,331 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.173
2022-04-14 21:20:03,466 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.105
2022-04-14 21:20:03,647 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.121
2022-04-14 21:20:03,837 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.157
2022-04-14 21:20:04,019 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.148
2022-04-14 21:20:04,193 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.141
2022-04-14 21:20:04,418 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.119
2022-04-14 21:20:04,578 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.116
2022-04-14 21:20:04,724 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.116
2022-04-14 21:20:04,873 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.116
2022-04-14 21:20:05,016 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.114
2022-04-14 21:20:05,235 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.189
2022-04-14 21:20:05,390 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.124
2022-04-14 21:20:05,539 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.121
2022-04-14 21:20:05,697 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.128
2022-04-14 21:20:05,850 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.121
2022-04-14 21:20:06,073 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.191
2022-04-14 21:20:06,198 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.117
2022-04-14 21:20:06,369 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.148
2022-04-14 21:20:06,514 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.144
2022-04-14 21:20:06,669 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.145
2022-04-14 21:20:06,671 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded jinja.render
2022-04-14 21:20:06,672 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded yaml.render
2022-04-14 21:20:06,685 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded saltutil.refresh_modules
2022-04-14 21:20:06,686 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded event.fire
2022-04-14 21:20:09,485 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded pillar.get
2022-04-14 21:20:09,498 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded random.seed
2022-04-14 21:20:09,545 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded grains.get
2022-04-14 21:20:09,690 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded mount.active
2022-04-14 21:20:09,692 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded cmd.run_stdout
2022-04-14 21:20:09,780 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded config.option
2022-04-14 21:20:09,780 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded test.configurable_test_state
2022-04-14 21:20:09,908 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded systemd.booted
2022-04-14 21:20:09,913 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded service.start
2022-04-14 21:20:09,913 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded service.dead
2022-04-14 21:20:09,947 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded file.managed
2022-04-14 21:20:09,956 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded file.user_to_uid
2022-04-14 21:20:09,958 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded cp.cache_file
2022-04-14 21:20:10,128 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.169
2022-04-14 21:20:10,148 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded yaml.serialize
2022-04-14 21:20:10,183 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded monrun.present
2022-04-14 21:20:10,226 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded pkg.install
2022-04-14 21:20:10,227 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded pkg.installed
2022-04-14 21:20:10,397 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded path.which
2022-04-14 21:20:10,456 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded args.clean_kwargs
2022-04-14 21:20:10,513 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.000
2022-04-14 21:20:10,731 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.120
2022-04-14 21:20:11,132 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.312
2022-04-14 21:20:13,723 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded timezone.system
2022-04-14 21:20:14,124 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded cmd.run
2022-04-14 21:20:14,371 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded state.check_result
2022-04-14 21:20:14,378 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded strm_report.returner
2022-04-14 21:20:14,400 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded rawfile_json.returner
2022-04-14 21:20:14,436 [salt.loader.lazy :253 ][WARNING ][53183] deepcopy took 0.002
2022-04-14 21:20:14,439 [salt.utils.lazy  :99  ][DEBUG   ][53183] LazyLoaded highstate.output

Versions Report

salt --versions-report 
Salt Version:
          Salt: 3004.1

Dependency Versions:
          cffi: 1.15.0
      cherrypy: Not Installed
      dateutil: 2.8.2
     docker-py: 5.0.3
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 3.0.3
       libgit2: Not Installed
      M2Crypto: 0.38.0
          Mako: 1.1.6
       msgpack: 1.0.3
  msgpack-pure: Not Installed
  mysql-python: 1.4.6
     pycparser: 2.21
      pycrypto: Not Installed
  pycryptodome: Not Installed
        pygit2: Not Installed
        Python: 3.9.12 (main, Apr 12 2022, 20:55:06)
  python-gnupg: 0.4.8
        PyYAML: 5.4.1
         PyZMQ: 22.3.0
         smmap: 5.0.0
       timelib: 0.2.4
       Tornado: 4.5.3
           ZMQ: 4.1.2

System Versions:
          dist: ubuntu 18.04 Bionic Beaver
        locale: utf-8
       machine: x86_64
       release: 4.19.60-12
        system: Linux
       version: Ubuntu 18.04 Bionic Beaver
@uhriap uhriap added Bug broken, incorrect, or confusing behavior needs-triage labels Apr 14, 2022
@OrangeDog OrangeDog added Core relates to code central or existential to Salt Pillar Performance severity-medium 3rd level, incorrect or bad functionality, confusing and lacks a work around and removed needs-triage labels Apr 14, 2022
@OrangeDog OrangeDog added this to the Approved milestone Apr 14, 2022
@uhriap
Copy link
Author

uhriap commented Apr 14, 2022

Another frequently called place with always new LazyLoader:

salt/salt/fileclient.py

Line 86 in 1568067

self.utils = salt.loader.utils(self.opts)

@frebib frebib linked a pull request Jul 7, 2023 that will close this issue
Open
3 tasks
frebib added a commit to frebib/salt that referenced this issue Jul 7, 2023
@frebib
Re-use the matchers loader object
3263931 
Avoid recreating it repeatedly for every match. This cuts our pillar top
matching time from ~5s down to <0.2s

Fixes: saltstack#61950
Signed-off-by: Joe Groocock <jgroocock@cloudflare.com>
@frebib frebib linked a pull request Jul 7, 2023 that will close this issue
Open
3 tasks
@dwoz dwoz self-assigned this Aug 14, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dwoz dwoz

Labels
Bug broken, incorrect, or confusing behavior Core relates to code central or existential to Salt Performance Pillar severity-medium 3rd level, incorrect or bad functionality, confusing and lacks a work around
Projects
None yet
Milestone
Approved
3 participants
@OrangeDog @dwoz @uhriap