cs-script
cs-script copied to clipboard
oleg-shilo
Huge script startup delay with v4.7.2.0 compared to v4.2.0.0
Hi!
We have recently updated CS-Script from 4.2.0.0 to 4.7.2.0 We have around 130 script files which act as a CI system for configure, build, test, create documentation etc. So the scripts import the required other scripts with //css_import With 4.2.0.0 we had CS-Script preparation times like this (printed via cscs -verbose2):
Initialization time: 1304,2658 msec
Compilation time: 4439,3866 msec
Total load time: 7496,6287 msec
With 4.7.2.0 the preparation times got really worse:
Initialization time: 2480,2409 msec
Compilation time: 4462,7088 msec
Total load time: 30841,0176 msec
This huge overhead occurs each time a script is started.
I've searched a little in the repository history and I think the main reason for the slowdown is:
https://github.com/oleg-shilo/cs-script/issues/297
If I just change back "true" to "false" in
https://github.com/oleg-shilo/cs-script/blob/master/src/cscs/ScriptParser.cs#L249
I get the better times back (not as good as before but far better):
Initialization time: 2506,2363 msec
Compilation time: 3569,1454 msec
Total load time: 9911,4886 msec
By the way the comment on this line of code still says "//do not parse it yet (the third param is false)"
We are using the scripts interactively on the console quite often and this huge delay of over 30 seconds each time a script is executed is really painful.
Do you have an idea how this could be fixed (or reverted or improved)?
Maybe:
-
Make this https://github.com/oleg-shilo/cs-script/issues/297 optional via some switch or bring back the old behavior via a switch like (-disable_deep_parse) or something like that.
-
Cache the long parsing process result somehow, so that it does not need to be executed each time a script is started. So we would have this overhead only once (or partially when a script //css_import has been changed)
Thanks for your help in advance.
I'm open for discussion or testing or whatever you need.
Disabling parisng from cli is an option.
-
But before we consider this can you please test the attached v4.8.1 build. I found that the latest change was incomplete and the old
importedFile.ProcessFilewas called twice. I fixed it and want to see how better the performance is. -
you can always disable any caching-related parsing (the subject of the latest fix by passing
-c:0from the CLI. Though it's unlikely it would make much difference. And you in fact want to use caching unless you know it's not going to benefit you. But it's easy to test. -
Parsing scripts should only happen if they are modified since the last execution or have just been created. So I do not expect the delay to be present in every startup. Do you always execute freshly created scripts?
Thanks for your quick answer.
Here are the results with your package:
del -r $env:temp\csscript.core\
cscs -version
C# Script execution engine (.NET Core). Version 4.8.1.0.
cscs -verbose2 .\our_script.cs
Initialization time: 2583,7956 msec
Compilation time: 3595,7104 msec
Total load time: 27716,5716 msec
Execute the same again (no scripts are modified or created):
cscs -verbose2 .\our_script.cs
Initialization time: 2678,3647 msec
Compilation time: 3442,2494 msec
Total load time: 24182,5478 msec
cscs -verbose2 .\our_script.cs
Initialization time: 2600,2557 msec
Compilation time: 6328,5954 msec
Total load time: 27719,7592 msec
cscs -verbose2 .\our_script.cs
Initialization time: 2541,5031 msec
Compilation time: 4493,4298 msec
Total load time: 25113,5728 msec
cscs -verbose2 .\our_script.cs
Initialization time: 2583,7482 msec
Compilation time: 3432,7109 msec
Total load time: 24067,6149 msec
cscs -verbose2 .\our_script.cs
Initialization time: 2678,2312 msec
Compilation time: 3364,886 msec
Total load time: 24334,2406 msec
Again with CS-Script tmp folder (and cache inside) deleted before once:
del -r $env:temp\csscript.core\
cscs -verbose2 .\our_script.cs
Initialization time: 2605,3853 msec
Compilation time: 3712,2492 msec
Total load time: 29207,2682 msec
cscs -verbose2 .\our_script.cs
Initialization time: 2617,7998 msec
Compilation time: 3544,6354 msec
Total load time: 25790,5889 msec
cscs -verbose2 .\our_script.cs
Initialization time: 2604,9118 msec
Compilation time: 3442,4242 msec
Total load time: 25439,9125 msec
We have this overhead each time. No script has been changed/modified/created between the executions. It seems that caching to avoid parsing again does not work for us.
Strange. The engine misbehaves.
This is the rest I just prepared for you:
Can you check that it works the same way in your environment? Because it is supposed to be lightning-fast on the second run (only 'Initialization time' overhead). I expect it to be about 2.5 seconds on your system.
please test the attached script
cs-script_#336.zip
I get this with your script:
css -profile b
> ----------------
Building with dotnet engine...
Initialization time: 146,7283 msec
Compilation time: 2838,5855 msec
Total load time: 2993,1192 msec
> ----------------
b
a
css -profile b
Loading script from cache...
> ----------------
Initialization time: 152,341 msec
> ----------------
b
a
Here it seems to use the cache as expected.
So what in our scripts could prevent the proper caching? I have the cs-script solution running in Visual Studio and could debug with our scripts. Maybe you can give me some hints where to look at to check for the cache detection. Or do you have another idea how to proceed?
Perfect. Meaning it's possible. Let's see how to bring it all together.
The preferred option is to collapse your implementation to a "hello world" style scenario, remove sensitive data, ensure that it still shows the problem and share it with me. It is much simpler than you explaining to me what you are observing.
If we have to opt for you to debug the solution then see what is triggering the IsOutOfDate returning true:
In csscript.cs file:
After some debugging i have found this:
We have some imported files in the cache i_...cs which gets deleted from the cache by the line "parser.DeleteImportedFiles();" in csscript.cs
if (!options.DBG) //.pdb and imported files might be needed for the debugger
{
//parser.DeleteImportedFiles();
Utils.FileDelete(pdbFileName);
}
When I remove the line, the i_....cs files stay in the cache and the next script execution will find everything in the cache, and will use the cache. Otherwise the method "static public bool IsOutOfDate(string script, string assembly)" will return false when the first deleted i_...cs file is not found in the cache.
You must have. :)
I can reproduce the problem by simply inserting static main in the a.cs script in my sample.
Will fix it in a day or two
Yes, we have scripts which are imported in some use case and are called as separate script in other cases. So they have their own static main too.
Thanks for your quick help.
In the meantime you can trick the system to do caching the right way by forcing it to compile scripts in debug mode.
Just pass -dbg and it will do the trick
css -profile -dbg b.cs
I've tested your v4.8.1.0 release now and the caching seems to work fine now:
cscs -profile .\our_script.cs
> ----------------
Building with dotnet engine...
Initialization time: 2548,2812 msec
Compilation time: 3585,3955 msec
Total load time: 27875,0149 msec
> ----------------
cscs -profile .\our_script.cs
Loading script from cache...
> ----------------
Initialization time: 2511,7658 msec
> ----------------
I still want to ask you if it would be possible to shorten the parsing maybe with a switch -shallow_parse or -no_deep_parse like I've mentioned in my first post: https://github.com/oleg-shilo/cs-script/issues/336#issue-1788764793
This would help a lot when we develop/modify/extend our set of scripts so that we wouldn't have to wait around 30 seconds for each script modification.
Note: The simple "true"/"false" trick I've mentioned earlier does not work anymore with your latest code changes. Before this reduced the parsing time from 30 seconds back to around 10 seconds parsing time (as it was in v4.2.0.0).
What do you think? Would it be possible to have a "-shallow_parse" switch to speed up parsing (like it was for us in v4.2.0.0)?
I had another look at the problem but dug deeper, down to the origins of the problem. The outcome is very positive. I will be rolling back the change of Nov 2021 that triggered all this.
It all started with the #260 fix and then was extended for #297. The problem was caused by the master script still using the unprocessed imported script with 'static Main'. The fix was to force the processing of the imported script. While the fix addressed the issue it triggered (due to the compromised caching) the performance degradation that you reported.
But your report let me look at the raw reason and actually fix the caching/importing. As a result, forcing is no longer needed. Thus the fix for this very issue #336 is also addressing the original #260 and #297.
I have re-conducted the tests for #260 and #297. They do fail for the v4.2.0.0 (as expected) but the latest codebase addresses them completely.
Thus I am happy to make a new release with the change you are asking.
Please check the pre-release: https://github.com/oleg-shilo/cs-script/releases/tag/v4.8.2.0
I've tested your v4.8.2.0 pre-release now and the initial parsing is now really faster:
cscs -version
C# Script execution engine (.NET Core). Version 4.8.2.0.
del -r $env:temp\csscript.core\
cscs -profile .\our_script.cs
> ----------------
Building with dotnet engine...
Initialization time: 2577,5785 msec
Compilation time: 3542,5087 msec
Total load time: 13931,2947 msec
> ----------------
cscs -profile .\our_script.cs
Loading script from cache...
> ----------------
Initialization time: 2516,1818 msec
> ----------------
But still the 4.2.0.0 was faster (from my first post https://github.com/oleg-shilo/cs-script/issues/336#issue-1788764793):
Initialization time: 1304,2658 msec
Compilation time: 4439,3866 msec
Total load time: 7496,6287 msec
There still have to be some additional (maybe unnecessary) parsing steps compared to 4.2.0.0 somewhere inside. Or maybe something is done too often now or files are parsed more than once or so.
Here are the search directories we have when using -verbose2. I have replaced some strings in the paths because of privacy.
SearchDirectories:
------- (local dirs) -------
0 - C:\Users\XXX\folder1\folder2\folder3\folder4\folder5
1 - C:\Program Files\cs-script
------- (dirs from cmd args) -------
------- (dirs from code) -------
2 - C:\Users\XXX\folder1\folder2\folder3\folder4\folder5\Scripts\Common
------- (dirs from config) -------
3 - C:\Program Files\cs-script\lib
4 - C:\ProgramData\cs-script\commands
5 - C:\ProgramData\cs-script\inc
------- (cs-script special dirs) -------
6 - C:\Users\XXX\AppData\Local\Temp\csscript.core\cache\81821667
7 - C:\Users\XXX\.nuget\packages\cs-script\4.6.5\lib\netstandard2.0
8 - C:\Users\XXX\.nuget\packages\Microsoft.CodeAnalysis.CSharp.Scripting\4.1.0\lib\netcoreapp3.1
9 - C:\Users\XXX\.nuget\packages\Microsoft.CodeAnalysis.Scripting.Common\4.1.0\lib\netcoreapp3.1
10 - C:\Users\XXX\.nuget\packages\Microsoft.Extensions.DependencyModel\6.0.0\lib\netstandard2.0
11 - C:\Users\XXX\.nuget\packages\System.Runtime.Loader\4.3.0\lib\netstandard1.5
12 - C:\Users\XXX\.nuget\packages\System.Runtime.CompilerServices.Unsafe\6.0.0\lib\netcoreapp3.1
13 - C:\Users\XXX\.nuget\packages\System.Text.Encodings.Web\6.0.0\lib\netcoreapp3.1
14 - C:\Users\XXX\.nuget\packages\System.Text.Json\6.0.0\lib\netcoreapp3.1
15 - C:\Users\XXX\folder1\folder2\folder3\folder4\folder5\Scripts\
16 - C:\Users\XXX\folder1\folder2\folder3\folder4\folder5\Scripts\Common
17 - C:\Users\XXX\folder1\folder2\folder3\folder4\folder5\Scripts\Common
18 - C:\Users\XXX\folder1\folder2\folder3\folder4\folder5\Scripts\Common
Here for example the path "C:\Users\XXX\folder1\folder2\folder3\folder4\folder5\Scripts\Common" is present 4 times. When the parsing is iterating over this list it could do something 4 times. Also I assume the "-----" separator lines in the list are iterated and checked if they are a folder very often.
Let's clarify all your points.
-
"But still the 4.2.0.0 was faster..." It is not something that I can work with. When I tested a simple 2 levels nesting import/include of 11 children scripts could not detect any significant performance difference In fact v4.2.0 was consistently 10% slower. I have attached the sample that profiles the test scenario. deep.zip The fact that one version is marginally faster than another one is only reason for action if the difference is significant and has no valid justification. Right now I can't even detect it. The best way is to define a standard test case that shows the problem. I just have attached such a test. So please try it and possibly update to reproduce the problem you see in your environment. Then I will be able to look at it.
-
"Here for example the path "C:\Users\XXX\folder1\folder2\folder3\folder4\folder5\Scripts\Common" is present 4 times." Can you please share how you achieved that? All search dirs duplications are removed:
css -c:0 -profile -verbose -dir:rrr -dir:rrr script.cs // it produces only single rrr dir ------- (dirs from cmd args) ------- 2 - D:\dev\Galos\support\cs-script-#260\deep\rrr ------- (dirs from code) ------- -
"When the parsing is iterating over this list it could do something 4 times." No it could not. In the attached test the same dep_script.cs is referenced 10 times and yet it is imported only once.
-
"Also I assume the "-----" separator..." The separator is ignored completely.
Let us have a look a each issue separately. For the "multiple included folders" I have debugged it and created https://github.com/oleg-shilo/cs-script/pull/339 I hope my short description in the commit message is enough to reproduce the problem. It is based on the deep.zip you have attached here https://github.com/oleg-shilo/cs-script/issues/336#issuecomment-1630753511
Excellent
The "multiple included folders" were already handled for the dirs coming from CLI (my prev example), but it was not handled from the imported scripts (your example). This is what I was missing.
I have merged the PR. I have also added the fix for redirecting the probing dirs to the correct section of the search dirs ------- (dirs from code) -------.
The impact is very minimal. Unfortunatelly. The probing is extremely fast even if it is repeated again and again. I suspect that there is something else that is impacting your performance in your tests.
I would like to get to the bottom of it. Even if I end up confirming that the system works as expected. I only see two possibilities for different behaviour in your and my environment:
- The problem is caused by the environment but not by the code. It's easy to check. Just run deep.zip in your env and let's see if the outcome is the same as mine.
- The problem is caused by the scripts you are running. It's difficult to check. If we have to do this then I will need to get some sort of alternative deep.zip that shows the problem. But iyt means more work for you with preparing such test case. :(
So let's check the possible cause #1 for the start.
Here is the output of the deep.zip scripts on my machine:
C:\test\deep>css -c:0 -profile -verbose script
> ----------------
Provider:
Script engine: C:\Program Files\cs-script\cscs.dll
Compiler engine: dotnet (C:\Program Files\dotnet\dotnet.exe)
Console Encoding: Codepage - 437 (Codepage - 437) - system default
CurrentDirectory: C:\test\deep
NuGet manager: dotnet
NuGet cache: C:\Users\XXX\.nuget\packages
Executing: C:\test\deep\script.cs
Script arguments:
SearchDirectories:
------- (local dirs) -------
0 - C:\test\deep
1 - C:\Program Files\cs-script
------- (dirs from cmd args) -------
------- (dirs from code) -------
------- (dirs from config) -------
2 - C:\Program Files\cs-script\lib
3 - C:\ProgramData\cs-script\commands
4 - C:\ProgramData\cs-script\inc
------- (cs-script special dirs) -------
5 - C:\Users\XXX\AppData\Local\Temp\csscript.core\cache\-1396100874
> ----------------
Compiling script...
Precompilers:
0 - script.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
1 - dep_script.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
2 - script_0.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
3 - script_1.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
4 - script_2.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
5 - script_3.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
6 - script_4.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
7 - script_5.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
8 - script_6.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
9 - script_7.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
10 - script_8.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
11 - script_9.cs -> csscript.DefaultPrecompiler
from C:\Program Files\cs-script\cscs.dll
Output file:
C:\Users\XXX\AppData\Local\Temp\csscript.core\18384.3dad23c7-8125-45b9-b23c-91242cc9a433.dll
Files to compile:
0 - C:\test\deep\script.cs
1 - C:\test\deep\dep_script.cs
2 - C:\test\deep\script_0.cs
3 - C:\test\deep\script_1.cs
4 - C:\test\deep\script_2.cs
5 - C:\test\deep\script_3.cs
6 - C:\test\deep\script_4.cs
7 - C:\test\deep\script_5.cs
8 - C:\test\deep\script_6.cs
9 - C:\test\deep\script_7.cs
10 - C:\test\deep\script_8.cs
11 - C:\test\deep\script_9.cs
12 - C:\Users\XXX\AppData\Local\Temp\csscript.core\cache\-1396100874\script.attr.g.cs
References:
0 - System.Core
1 - System
> ----------------
> ----------------
> ----------------
Building with dotnet engine...
Initialization time: 271,5815 msec
Compilation time: 5286,3964 msec
Total load time: 5603,7492 msec
> ----------------
Hello
Here just the times of some more runs:
Initialization time: 271,1068 msec
Compilation time: 2969,4062 msec
Total load time: 3334,9389 msec
Initialization time: 323,4029 msec
Compilation time: 2826,2569 msec
Total load time: 3189,4043 msec
Initialization time: 333,7832 msec
Compilation time: 2851,5824 msec
Total load time: 3219,5736 msec
Initialization time: 303,5722 msec
Compilation time: 2919,3591 msec
Total load time: 3333,7311 msec
Initialization time: 333,7887 msec
Compilation time: 2897,1023 msec
Total load time: 3302,0968 msec
And how is the same test on your machine but for v4.2.0 This is what I am trying to get. To see if the delay is caused by the engine changes since v4.2.0 or by the difference in environments (yours and mine)
PS C:\test\deep> & 'C:\Program Files\cs-script.win.v4.8.2.0\cscs' -c:0 -profile script
> ----------------
Building with dotnet engine...
Initialization time: 238,7979 msec
Compilation time: 2889,8845 msec
Total load time: 3166,8853 msec
> ----------------
Hello
PS C:\test\deep> & 'C:\Program Files\cs-script_4.2\cscs' -c:0 -profile script
> ----------------
Building with dotnet engine...
Initialization time: 279,2685 msec
Compilation time: 2947,9243 msec
Total load time: 3340,5317 msec
> ----------------
Hello
With our script:
& 'C:\Program Files\cs-script.win.v4.8.2.0\cscs' -c:0 -profile .\our_script.cs
> ----------------
Building with dotnet engine...
Initialization time: 2653,7477 msec
Compilation time: 3636,3044 msec
Total load time: 10142,8931 msec
> ----------------
& 'C:\Program Files\cs-script_4.2\cscs' -c:0 -profile .\our_script.cs
> ----------------
Building with dotnet engine...
Initialization time: 1124,6724 msec
Compilation time: 3533,6222 msec
Total load time: 5907,4024 msec
> ----------------
We have these 5 top level scripts. I've made some more measurements with these 5 scripts and 4.2.0.0 and 4.8.2.0 The rows like "SearchDirectories" and so on are from the -verbose2 output and should illustrate how many scripts are referenced or imported or are compiled etc.
Great, it means that the difference in our environments plays no role in the performance degradation of the latest cs-script when executing your production scripts.
It is evidence that there is something in your script codebase that triggers the performance penalty. The data from the post above indicates that the penalty is much higher than one would expect based on a very modest increase in the initialization time. Thus I need to use the provider to find the major contributor/offender. This can only be done if I have a test case that shows the problem when I run it in my environment.
This leaves you with only two options:
- Assist me by building such a test case (e.g. by sharing a sanitized version of your Documentation.cs).
There are two challenges with this approach:
It requires effort from both of us.
I may discover that the performance difference may be well justified and is to stay. IE it is an unfortunate side effect of the valid 4.2.0->4.8.1 change. In this case you will have to go with option
#2 - Take the performance as is but start relying strongly on caching. You will, of course, need to understand the impact on your product's usability.
Just a short update.
I could not create a test case till now. When I remove all our productive code from the 21/22 script files for Configure.cs the times go down and are more or less equal then:
& 'C:\Program Files\cs-script.win.v4.8.2.0\cscs' -c:0 -profile .\Configure.cs
> ----------------
Building with dotnet engine...
Initialization time: 299,006 msec
Compilation time: 3072,4367 msec
Total load time: 4193,7568 msec
> ----------------
& 'C:\Program Files\cs-script.win.v4.8.2.0\cscs' -c:0 -profile .\Configure.cs
> ----------------
Building with dotnet engine...
Initialization time: 295,5027 msec
Compilation time: 2982,2588 msec
Total load time: 4106,1714 msec
> ----------------
& 'C:\Program Files\cs-script_4.2\cscs' -c:0 -profile .\Configure.cs
> ----------------
Building with dotnet engine...
Initialization time: 314,5626 msec
Compilation time: 3008,3831 msec
Total load time: 4190,2988 msec
> ----------------
& 'C:\Program Files\cs-script_4.2\cscs' -c:0 -profile .\Configure.cs
> ----------------
Building with dotnet engine...
Initialization time: 319,9567 msec
Compilation time: 2931,256 msec
Total load time: 4101,9095 msec
> ----------------
So it is not the folder structure, the used //css_import or the used //cs_dir directives.
When adding parts of the script code back step by step the times go up again. It is not easy to add just parts back because everything depends on other parts and so on. I could not find a significant piece of code which would show a non-linear increase of the times.
Then I also tried to make your deep.zip sample more complex to get the same behavior we have in our scripts. But also without success till now.
Maybe I'll try to debug it by myself in the next days when I find some time.
This is what I was afraid of. :(
I encourage you to consider option #2. The chances are that this performance penalty has a legitimate reason so we may not be able to avoid it anyway.
But... if you want to take your chances I suggest you use a good .NET profiler and then compare the behaviour of v4.2.0 vs v4.8.2