I am using a python module for ERP communication, however I am troubleshooting some performance issues. After some testing I discovered that the same function with identical code in the script console or a single python-file directly in site-packages folder runs very fast, while calling the same function from a module e.g. module.components.erp.jobs.checksomething(value) is incredibly slow.
In order to test this I put the code in a while loop (1000x) and measured the time. For comparison the same code in the console or single python-file takes 0.0 s and the same code called from the module takes 4.9 s. Please help me solve this.
I tried shallowing or wrapping the import like this:
from module.components.erp.jobs import checksomething
or
_checksomething = module.components.erp.jobs.checksomething
Both do not change anything
The code in script console:
> import time
> from module.components.erp.jobs import checksomething as checksomething1
> from test_file import checksomething as checksomething2
> value = "ABCABC.4931"
> now1 = time.time()
> for _ in range(1000):
> x = checksomething1(value)
> now2 = time.time()
> for _ in range(1000):
> x = checksomething2(value)
> now3 = time.time()
>
> now2 - now1 # outputs: 4.85899996758
> now3 - now2 # outputs: 0.0090000629425
site-packages\module\components\erp\jobs.py
> """
> Bunch of code
> """
> def checksomething(value):
> import re
> matches = re.findall(r"(\w+)\.?(\d+)?", value)
> if len(matches) >= 1 and len(matches[0]) >= 2 and len(matches[0][0]) > 0:
> return str(matches[0][0])
> else:
> raise Exception("Invalid value '{0}'".format(value))
Same code in:
site-packages\test_file.py
> def checksomething(value):
> import re
> matches = re.findall(r"(\w+)\.?(\d+)?", value)
> if len(matches) >= 1 and len(matches[0]) >= 2 and len(matches[0][0]) > 0:
> return str(matches[0][0])
> else:
> raise Exception("Invalid value '{0}'".format(value))
Not sure if its impacting the speed but do not import libraries inside of a function definition, especially in a project library script. Move it to sit outside of the function definition (ideally at the top of the file).
Also consider compiling and caching the re matcher (outside of the function definition) in a top level variable, and using the Java RE classes (java.util.regex.Matcher and java.util.regex.Pattern) instead of python.
When doing benchmarking, it is best practice to use Java's nano time. I would run your tests again using this method.
from java.lang import System
t1 = System.nanoTime()
# script goes brrrr
print System.nanoTime() - t1
2 Likes
Yea, tried that aswell... doesn't make any difference
Is it slow every time you run it or just the first time? If you call it once as a throwaway and then time it what happens?
1 Like
Also, have you separated this script out into its own file at the same depth and then tried calling it?
Okay, the results with the nanoTime() function are:
6349360300 # module.components.erp.jobs.checksomething
17205901 # test_file.checksomething
7057100 # Directly in console
So similar results
Yes I did, thats basically the testing I did as described above. When doing this it is much faster.
I did some testing, seems to run slow each time, see below
6598600 # First call of module.components.erp.jobs.checksomething
5462810600 # 1000 sequential calls (avg. 5462810)
EDIT:
Actually, does seems to have some kind of impact. Below some results for running testing first and second time in script console:
Jython 2.7.3, executing locally in the Designer.
Press (Ctrl + Space) to activate autocompletion.
>>>
START
1000 calls at depth module.components.erp.test_file.checksomething: 8.0734377 s, avg 0.0080735527 s
1000 calls at depth module.components.test_file.checksomething: 5.5843203 s, avg 0.005584376199 s
1000 calls at depth module.test_file.checksomething: 3.1591856 s, avg 0.0031594073 s
1000 calls at depth test_module.test_file.checksomething: 3.219457 s, avg 0.003219652 s
1000 calls at depth test_file.checksomething: 0.011500399 s, avg 1.1554099e-05 s
>>>
START
1000 calls at depth module.components.erp.test_file.checksomething: 3.5183277 s, avg 0.0035184247 s
1000 calls at depth module.components.test_file.checksomething: 3.053373499 s, avg 0.0030534299 s
1000 calls at depth module.test_file.checksomething: 3.018941601 s, avg 0.003019001701 s
1000 calls at depth test_module.test_file.checksomething: 3.2018797 s, avg 0.0032019709 s
1000 calls at depth test_file.checksomething: 0.0047055 s, avg 4.7444e-06 s
>>>
To make sure I'm understanding correctly, you made a file at site-packages/module/components/erp/test_file.py, put only checksomething in there and then called it, and it ran faster? Or are you talking about the file at base depth that you made(site-packages/test_file.py)?
1 Like
Not the main problem, but make sure that in project scripts you put the imports outside of the function (top level). This should save some execution time by not importing every time the function is called.
Great suggestion! No, made the file at base depth. Copied the test_file.py to the /site-packages/module/components/erp/test_file.py (without any other content besides the checksomething function).
single call at /site-packages/module/components/erp/test_file.py: 5126799
1000 calls at /site-packages/module/components/erp/test_file.py: 4170137000
1000 calls at /site-packages/test_file.py: 5000199
1000 calls in console: 7918000
EDIT:
Did some more testing
1000 calls at depth module.components.erp.test_file.checksomething: 4.7632177 s, avg 0.0047633
1000 calls at depth module.components.test_file.checksomething: 4.9434838 s, avg 0.0049435599
1000 calls at depth module.test_file.checksomething: 4.2983209 s, avg 0.004298386599
1000 calls at depth test_file.checksomething: 0.005669799 s, avg 5.716099e-06
EDIT2:
Created a test_module to put test_file.py in. Seems like that once there is a module involved it gets very slow ...
1000 calls at depth module.components.erp.test_file.checksomething: 3.152241601 s, avg 0.003152348301 s
1000 calls at depth module.components.test_file.checksomething: 3.019533999 s, avg 0.0030195856 s
1000 calls at depth module.test_file.checksomething: 2.9465203 s, avg 0.0029467295 s
1000 calls at depth test_module.test_file.checksomething: 2.9453126 s, avg 0.002945374199 s
1000 calls at depth test_file.checksomething: 0.0055201 s, avg 5.5673e-06 s
What Ignition version are you on? I'm 8.1.44.
I'm attempting to replicate at least in project library scripts, and the most I'm getting with the import in the function definition is 20ms total, with typical total time per 1000 calls in the 3-4ms range.
Moving the import outside of the function def, along with compiling the RE pulls it down closer to 2-3ms, with the call in the console almost always matching time the call in the project library. There is a slight difference, with the module call being slightly higher. I do occasionally get a high time call.
1 Like
Updating as we speak, from 8.1.44 to 8.1.48. Will let the results know.
Think the major difference here is that I am developing the module in sites-packages and not project library scripts
Same results for 8.1.48...
Okay so, this behavious only seems to occur when using a module in the /site-packages/ folder. Using the same path for a project library script this seems to work normally, also when there is a single folder in the /site-packages/ folder.
4.0817866 s, avg 0.0040818749 s -> 1000 calls at /site-packages/module.components.erp.test_file.checksomething
4.7811206 s, avg 0.0047811821 s -> 1000 calls at /site-packages/module.components.test_file.checksomething
3.3498809 s, avg 0.0033499429 s -> 1000 calls at /site-packages/module.test_file.checksomething
4.029137501 s, avg 0.004029197701 s -> 1000 calls at /site-packages/test_module.test_file.checksomething
0.005512301 s, avg 5.652401e-06 s -> 1000 calls at /site-packages/test_file.checksomething
0.006463801 s, avg 6.545701e-06 s -> 1000 calls at prooject library package test_module1.test_file.checksomething
That sounds to me like it's something with path resolution, maybe?
Not sure how ignition handles that
Same results when calling the module from pylib-folder instead of site-packages...