[WIP] enable persistent caching of vcvars on win32

Setting env var SCONS_CACHE_MSVC_CONFIG enables a filesystem cache
of vcvars results, making them persistent across scons runs. On
test runs (notably our CI system) this helps a lot; in normal usage
where you run one scons invocation at a time instead of many hundreds
in a test run it will make things a little more responsive (esp on
vs2019) but the impact will be much smaller.

Signed-off-by: Mats Wichmann <mats@linux.com>

4 files changed, 102 insertions, 57 deletions

diff --git a/src/engine/SCons/Tool/MSCommon/common.py b/src/engine/SCons/Tool/MSCommon/common.py
index c3ba8e5..0a7e0ef 100644
--- a/src/engine/SCons/Tool/MSCommon/common.py
+++ b/src/engine/SCons/Tool/MSCommon/common.py
@@ -28,6 +28,7 @@ from __future__ import print_function
 __revision__ = "__FILE__ __REVISION__ __DATE__ __DEVELOPER__"
 
 import copy
+import json
 import os
 import subprocess
 import re
@@ -44,12 +45,39 @@ elif LOGFILE:
     except ImportError:
         debug = lambda message: open(LOGFILE, 'a').write(message + '\n')
     else:
-        logging.basicConfig(filename=LOGFILE, level=logging.DEBUG)
+        logging.basicConfig(
+            format='%(relativeCreated)05dms:pid%(process)05d:MSCommon/%(filename)s:%(message)s',
+            filename=LOGFILE,
+            level=logging.DEBUG)
         debug = logging.getLogger(name=__name__).debug
 else:
     debug = lambda x: None
 
 
+CONFIG_CACHE = os.environ.get('SCONS_CACHE_MSVC_CONFIG', None)
+CONFIG_FILE = os.path.join(os.path.expanduser('~'), '.scons_msvc_cache')
+
+
+def read_script_env_cache():
+    """ fetch cached env vars if requested, else return empty dict """
+    envcache = {}
+    if CONFIG_CACHE:
+        try:
+            with open(CONFIG_FILE, 'r') as f:
+                envcache = json.load(f)
+        except FileNotFoundError:
+            pass
+    return envcache
+
+
+def write_script_env_cache(cache):
+    """ write out cach of env vars if requested """
+    if CONFIG_CACHE:
+        with open(CONFIG_FILE, 'w') as f:
+            #TODO: clean up if it fails
+            json.dump(cache, f, indent=2)
+
+
 _is_win64 = None
 
 def is_win64():
@@ -207,14 +235,15 @@ def get_output(vcbat, args = None, env = None):
     output = stdout.decode("mbcs")
     return output
 
-def parse_output(output, keep=("INCLUDE", "LIB", "LIBPATH", "PATH", 'VSCMD_ARG_app_plat')):
+KEEPLIST = ("INCLUDE", "LIB", "LIBPATH", "PATH", 'VSCMD_ARG_app_plat')
+def parse_output(output, keep=KEEPLIST):
     """
     Parse output from running visual c++/studios vcvarsall.bat and running set
     To capture the values listed in keep
     """
 
     # dkeep is a dict associating key: path_list, where key is one item from
-    # keep, and pat_list the associated list of paths
+    # keep, and path_list the associated list of paths
     dkeep = dict([(i, []) for i in keep])
 
     # rdk will  keep the regex to match the .bat file output line starts
diff --git a/src/engine/SCons/Tool/MSCommon/sdk.py b/src/engine/SCons/Tool/MSCommon/sdk.py
index ad57865..281c1e3 100644
--- a/src/engine/SCons/Tool/MSCommon/sdk.py
+++ b/src/engine/SCons/Tool/MSCommon/sdk.py
@@ -118,11 +118,11 @@ class SDKDefinition(object):
         if (host_arch != target_arch):
             arch_string='%s_%s'%(host_arch,target_arch)
 
-        debug("sdk.py: get_sdk_vc_script():arch_string:%s host_arch:%s target_arch:%s"%(arch_string,
+        debug("get_sdk_vc_script():arch_string:%s host_arch:%s target_arch:%s"%(arch_string,
                                                            host_arch,
                                                            target_arch))
         file=self.vc_setup_scripts.get(arch_string,None)
-        debug("sdk.py: get_sdk_vc_script():file:%s"%file)
+        debug("get_sdk_vc_script():file:%s"%file)
         return file
 
 class WindowsSDK(SDKDefinition):
@@ -286,14 +286,14 @@ InstalledSDKMap = None
 def get_installed_sdks():
     global InstalledSDKList
     global InstalledSDKMap
-    debug('sdk.py:get_installed_sdks()')
+    debug('get_installed_sdks()')
     if InstalledSDKList is None:
         InstalledSDKList = []
         InstalledSDKMap = {}
         for sdk in SupportedSDKList:
-            debug('MSCommon/sdk.py: trying to find SDK %s' % sdk.version)
+            debug('trying to find SDK %s' % sdk.version)
             if sdk.get_sdk_dir():
-                debug('MSCommon/sdk.py:found SDK %s' % sdk.version)
+                debug('found SDK %s' % sdk.version)
                 InstalledSDKList.append(sdk)
                 InstalledSDKMap[sdk.version] = sdk
     return InstalledSDKList
@@ -346,13 +346,13 @@ def get_default_sdk():
     return InstalledSDKList[0]
 
 def mssdk_setup_env(env):
-    debug('sdk.py:mssdk_setup_env()')
+    debug('mssdk_setup_env()')
     if 'MSSDK_DIR' in env:
         sdk_dir = env['MSSDK_DIR']
         if sdk_dir is None:
             return
         sdk_dir = env.subst(sdk_dir)
-        debug('sdk.py:mssdk_setup_env: Using MSSDK_DIR:{}'.format(sdk_dir))
+        debug('mssdk_setup_env: Using MSSDK_DIR:{}'.format(sdk_dir))
     elif 'MSSDK_VERSION' in env:
         sdk_version = env['MSSDK_VERSION']
         if sdk_version is None:
@@ -364,22 +364,22 @@ def mssdk_setup_env(env):
             msg = "SDK version %s is not installed" % sdk_version
             raise SCons.Errors.UserError(msg)
         sdk_dir = mssdk.get_sdk_dir()
-        debug('sdk.py:mssdk_setup_env: Using MSSDK_VERSION:%s'%sdk_dir)
+        debug('mssdk_setup_env: Using MSSDK_VERSION:%s'%sdk_dir)
     elif 'MSVS_VERSION' in env:
         msvs_version = env['MSVS_VERSION']
-        debug('sdk.py:mssdk_setup_env:Getting MSVS_VERSION from env:%s'%msvs_version)
+        debug('mssdk_setup_env:Getting MSVS_VERSION from env:%s'%msvs_version)
         if msvs_version is None:
-            debug('sdk.py:mssdk_setup_env thinks msvs_version is None')
+            debug('mssdk_setup_env thinks msvs_version is None')
             return
         msvs_version = env.subst(msvs_version)
         from . import vs
         msvs = vs.get_vs_by_version(msvs_version)
-        debug('sdk.py:mssdk_setup_env:msvs is :%s'%msvs)
+        debug('mssdk_setup_env:msvs is :%s'%msvs)
         if not msvs:
-            debug('sdk.py:mssdk_setup_env: no VS version detected, bailingout:%s'%msvs)
+            debug('mssdk_setup_env: no VS version detected, bailingout:%s'%msvs)
             return
         sdk_version = msvs.sdk_version
-        debug('sdk.py:msvs.sdk_version is %s'%sdk_version)
+        debug('msvs.sdk_version is %s'%sdk_version)
         if not sdk_version:
             return
         mssdk = get_sdk_by_version(sdk_version)
@@ -388,13 +388,13 @@ def mssdk_setup_env(env):
             if not mssdk:
                 return
         sdk_dir = mssdk.get_sdk_dir()
-        debug('sdk.py:mssdk_setup_env: Using MSVS_VERSION:%s'%sdk_dir)
+        debug('mssdk_setup_env: Using MSVS_VERSION:%s'%sdk_dir)
     else:
         mssdk = get_default_sdk()
         if not mssdk:
             return
         sdk_dir = mssdk.get_sdk_dir()
-        debug('sdk.py:mssdk_setup_env: not using any env values. sdk_dir:%s'%sdk_dir)
+        debug('mssdk_setup_env: not using any env values. sdk_dir:%s'%sdk_dir)
 
     set_sdk_by_directory(env, sdk_dir)
 
diff --git a/src/engine/SCons/Tool/MSCommon/vc.py b/src/engine/SCons/Tool/MSCommon/vc.py
index 0e4ef15..019d608 100644
--- a/src/engine/SCons/Tool/MSCommon/vc.py
+++ b/src/engine/SCons/Tool/MSCommon/vc.py
@@ -152,7 +152,7 @@ def get_msvc_version_numeric(msvc_version):
     return ''.join([x for  x in msvc_version if x in string_digits + '.'])
 
 def get_host_target(env):
-    debug('vc.py:get_host_target()')
+    debug('get_host_target()')
 
     host_platform = env.get('HOST_ARCH')
     if not host_platform:
@@ -165,7 +165,7 @@ def get_host_target(env):
 
     # Retain user requested TARGET_ARCH
     req_target_platform = env.get('TARGET_ARCH')
-    debug('vc.py:get_host_target() req_target_platform:%s'%req_target_platform)
+    debug('get_host_target() req_target_platform:%s'%req_target_platform)
 
     if  req_target_platform:
         # If user requested a specific platform then only try that one.
@@ -403,7 +403,7 @@ def find_batch_file(env,msvc_version,host_arch,target_arch):
     if pdir is None:
         raise NoVersionFound("No version of Visual Studio found")
 
-    debug('vc.py: find_batch_file() in {}'.format(pdir))
+    debug('find_batch_file() in {}'.format(pdir))
 
     # filter out e.g. "Exp" from the version name
     msvc_ver_numeric = get_msvc_version_numeric(msvc_version)
@@ -423,17 +423,17 @@ def find_batch_file(env,msvc_version,host_arch,target_arch):
         debug("Not found: %s" % batfilename)
         batfilename = None
 
-    installed_sdks=get_installed_sdks()
+    installed_sdks = get_installed_sdks()
     for _sdk in installed_sdks:
         sdk_bat_file = _sdk.get_sdk_vc_script(host_arch,target_arch)
         if not sdk_bat_file:
-            debug("vc.py:find_batch_file() not found:%s"%_sdk)
+            debug("find_batch_file() not found:%s"%_sdk)
         else:
             sdk_bat_file_path = os.path.join(pdir,sdk_bat_file)
             if os.path.exists(sdk_bat_file_path):
-                debug('vc.py:find_batch_file() sdk_bat_file_path:%s'%sdk_bat_file_path)
-                return (batfilename,sdk_bat_file_path)
-    return (batfilename,None)
+                debug('find_batch_file() sdk_bat_file_path:%s'%sdk_bat_file_path)
+                return (batfilename, sdk_bat_file_path)
+    return (batfilename, None)
 
 
 __INSTALLED_VCS_RUN = None
@@ -592,21 +592,37 @@ def reset_installed_vcs():
 #    env2 = Environment(tools='msvs')
 # we can greatly improve the speed of the second and subsequent Environment
 # (or Clone) calls by memoizing the environment variables set by vcvars*.bat.
-script_env_stdout_cache = {}
+#
+# Updated: by 2018, vcvarsall.bat had gotten so expensive it was breaking
+# CI builds because the test suite starts scons so many times and the existing
+# memo logic only helped with repeated calls within the same scons run;
+# with VS2019 it got even slower and an optional cache file was introduced.
+# The cache now also stores only the parsed vars, not the entire output
+# of running the batch file - saves a bit of time not parsing every time.
+
+script_env_cache = None
+
 def script_env(script, args=None):
-    cache_key = (script, args)
-    stdout = script_env_stdout_cache.get(cache_key, None)
-    if stdout is None:
+    global script_env_cache
+
+    if script_env_cache is None:
+        script_env_cache = common.read_script_env_cache()
+    cache_key = "{}--{}".format(script, args)
+    cache_data = script_env_cache.get(cache_key, None)
+    if cache_data is None:
         stdout = common.get_output(script, args)
-        script_env_stdout_cache[cache_key] = stdout
 
-    # Stupid batch files do not set return code: we take a look at the
-    # beginning of the output for an error message instead
-    olines = stdout.splitlines()
-    if olines[0].startswith("The specified configuration type is missing"):
-        raise BatchFileExecutionError("\n".join(olines[:2]))
+        # Stupid batch files do not set return code: we take a look at the
+        # beginning of the output for an error message instead
+        olines = stdout.splitlines()
+        if olines[0].startswith("The specified configuration type is missing"):
+            raise BatchFileExecutionError("\n".join(olines[:2]))
 
-    return common.parse_output(stdout)
+        cache_data = common.parse_output(stdout)
+        script_env_cache[cache_key] = cache_data
+        # once we updated cache, give a chance to write out if user wanted
+        common.write_script_env_cache(script_env_cache)
+    return cache_data
 
 def get_default_version(env):
     debug('get_default_version()')
@@ -635,12 +651,12 @@ def get_default_version(env):
         debug('installed_vcs:%s' % installed_vcs)
         if not installed_vcs:
             #msg = 'No installed VCs'
-            #debug('msv %s\n' % repr(msg))
+            #debug('msv %s' % repr(msg))
             #SCons.Warnings.warn(SCons.Warnings.VisualCMissingWarning, msg)
             debug('msvc_setup_env: No installed VCs')
             return None
         msvc_version = installed_vcs[0]
-        debug('msvc_setup_env: using default installed MSVC version %s\n' % repr(msvc_version))
+        debug('msvc_setup_env: using default installed MSVC version %s' % repr(msvc_version))
 
     return msvc_version
 
@@ -654,12 +670,12 @@ def msvc_setup_env_once(env):
         msvc_setup_env(env)
         env["MSVC_SETUP_RUN"] = True
 
-def msvc_find_valid_batch_script(env,version):
-    debug('vc.py:msvc_find_valid_batch_script()')
+def msvc_find_valid_batch_script(env, version):
+    debug('msvc_find_valid_batch_script()')
     # Find the host platform, target platform, and if present the requested
     # target platform
     platforms = get_host_target(env)
-    debug("vc.py: msvs_find_valid_batch_script(): host_platform %s, target_platform %s req_target_platform:%s" % platforms)
+    debug(" msvs_find_valid_batch_script(): host_platform %s, target_platform %s req_target_platform:%s" % platforms)
 
     host_platform, target_platform, req_target_platform = platforms
     try_target_archs = [target_platform]
@@ -683,7 +699,7 @@ def msvc_find_valid_batch_script(env,version):
         # Set to current arch.
         env['TARGET_ARCH']=tp
 
-        debug("vc.py:msvc_find_valid_batch_script() trying target_platform:%s"%tp)
+        debug("msvc_find_valid_batch_script() trying target_platform:%s"%tp)
         host_target = (host_platform, tp)
         if not is_host_target_supported(host_target, version):
             warn_msg = "host, target = %s not supported for MSVC version %s" % \
@@ -701,8 +717,8 @@ def msvc_find_valid_batch_script(env,version):
 
         # Try to locate a batch file for this host/target platform combo
         try:
-            (vc_script,sdk_script) = find_batch_file(env,version,host_platform,tp)
-            debug('vc.py:msvc_find_valid_batch_script() vc_script:%s sdk_script:%s'%(vc_script,sdk_script))
+            (vc_script, sdk_script) = find_batch_file(env, version, host_platform, tp)
+            debug('msvc_find_valid_batch_script() vc_script:%s sdk_script:%s'%(vc_script,sdk_script))
         except VisualCException as e:
             msg = str(e)
             debug('Caught exception while looking for batch file (%s)' % msg)
@@ -714,29 +730,29 @@ def msvc_find_valid_batch_script(env,version):
             continue
 
         # Try to use the located batch file for this host/target platform combo
-        debug('vc.py:msvc_find_valid_batch_script() use_script 2 %s, args:%s\n' % (repr(vc_script), arg))
+        debug('msvc_find_valid_batch_script() use_script 2 %s, args:%s' % (repr(vc_script), arg))
         found = None
         if vc_script:
             try:
                 d = script_env(vc_script, args=arg)
                 found = vc_script
             except BatchFileExecutionError as e:
-                debug('vc.py:msvc_find_valid_batch_script() use_script 3: failed running VC script %s: %s: Error:%s'%(repr(vc_script),arg,e))
+                debug('msvc_find_valid_batch_script() use_script 3: failed running VC script %s: %s: Error:%s'%(repr(vc_script),arg,e))
                 vc_script=None
                 continue
         if not vc_script and sdk_script:
-            debug('vc.py:msvc_find_valid_batch_script() use_script 4: trying sdk script: %s'%(sdk_script))
+            debug('msvc_find_valid_batch_script() use_script 4: trying sdk script: %s'%(sdk_script))
             try:
                 d = script_env(sdk_script)
                 found = sdk_script
             except BatchFileExecutionError as e:
-                debug('vc.py:msvc_find_valid_batch_script() use_script 5: failed running SDK script %s: Error:%s'%(repr(sdk_script),e))
+                debug('msvc_find_valid_batch_script() use_script 5: failed running SDK script %s: Error:%s'%(repr(sdk_script),e))
                 continue
         elif not vc_script and not sdk_script:
-            debug('vc.py:msvc_find_valid_batch_script() use_script 6: Neither VC script nor SDK script found')
+            debug('msvc_find_valid_batch_script() use_script 6: Neither VC script nor SDK script found')
             continue
 
-        debug("vc.py:msvc_find_valid_batch_script() Found a working script/target: %s/%s"%(repr(found),arg))
+        debug("msvc_find_valid_batch_script() Found a working script/target: %s/%s"%(repr(found),arg))
         break # We've found a working target_platform, so stop looking
 
     # If we cannot find a viable installed compiler, reset the TARGET_ARCH
@@ -756,7 +772,7 @@ def msvc_setup_env(env):
                    "compilers most likely not set correctly"
         SCons.Warnings.warn(SCons.Warnings.VisualCMissingWarning, warn_msg)
         return None
-    debug('msvc_setup_env: using specified MSVC version %s\n' % repr(version))
+    debug('msvc_setup_env: using specified MSVC version %s' % repr(version))
 
     # XXX: we set-up both MSVS version for backward
     # compatibility with the msvs tool
@@ -767,11 +783,11 @@ def msvc_setup_env(env):
 
     use_script = env.get('MSVC_USE_SCRIPT', True)
     if SCons.Util.is_String(use_script):
-        debug('vc.py:msvc_setup_env() use_script 1 %s\n' % repr(use_script))
+        debug('msvc_setup_env() use_script 1 %s' % repr(use_script))
         d = script_env(use_script)
     elif use_script:
         d = msvc_find_valid_batch_script(env,version)
-        debug('vc.py:msvc_setup_env() use_script 2 %s\n' % d)
+        debug('msvc_setup_env() use_script 2 %s' % d)
         if not d:
             return d
     else:
@@ -782,7 +798,7 @@ def msvc_setup_env(env):
         return None
 
     for k, v in d.items():
-        debug('vc.py:msvc_setup_env() env:%s -> %s'%(k,v))
+        debug('msvc_setup_env() env:%s -> %s'%(k,v))
         env.PrependENVPath(k, v, delete_existing=True)
 
     # final check to issue a warning if the compiler is not present
diff --git a/src/engine/SCons/Tool/MSCommon/vs.py b/src/engine/SCons/Tool/MSCommon/vs.py
index dfca48d..bac35d8 100644
--- a/src/engine/SCons/Tool/MSCommon/vs.py
+++ b/src/engine/SCons/Tool/MSCommon/vs.py
@@ -465,14 +465,14 @@ def get_vs_by_version(msvs):
     global InstalledVSMap
     global SupportedVSMap
 
-    debug('vs.py:get_vs_by_version()')
+    debug('get_vs_by_version()')
     if msvs not in SupportedVSMap:
         msg = "Visual Studio version %s is not supported" % repr(msvs)
         raise SCons.Errors.UserError(msg)
     get_installed_visual_studios()
     vs = InstalledVSMap.get(msvs)
     debug('InstalledVSMap:%s'%InstalledVSMap)
-    debug('vs.py:get_vs_by_version: found vs:%s'%vs)
+    debug('get_vs_by_version: found vs:%s'%vs)
     # Some check like this would let us provide a useful error message
     # if they try to set a Visual Studio version that's not installed.
     # However, we also want to be able to run tests (like the unit