Add timing report

Author: DrGeoff

src/compiletools/apptools.py

@@ -80,6 +80,12 @@ def add_base_arguments(cap, argv=None, variant=None):
     )
     cap.add("--version", action="version", version=__version__)
     cap.add("-?", action="help", help="Help")
+    cap.add(
+        "--time",
+        action="store_true",
+        default=False,
+        help="Time the execution of each subprocess (similar to gcc/clang -time flag)",
+    )
 
     if rich_rst_available and sys.version_info.major == 3 and sys.version_info.minor >= 9:
         cap.add("--man", "--doc", action=DocumentationAction)

src/compiletools/cake.py

@@ -15,6 +15,7 @@
 import compiletools.findtargets
 import compiletools.jobs
 import compiletools.wrappedos
+import compiletools.timing
 
 
 class Cake(object):
@@ -220,23 +221,27 @@ def process(self):
         if self.args.verbose > 4:
             print("Early scanning. Cake determining targets and implied files")
 
-        self._createctobjs()
+        with compiletools.timing.time_operation("create_ct_objects"):
+            self._createctobjs()
         recreateobjs = False
         if self.args.static and len(self.args.static) == 1:
-            self.args.static.extend(
-                self.hunter.required_source_files(self.args.static[0])
-            )
+            with compiletools.timing.time_operation("static_source_hunting"):
+                self.args.static.extend(
+                    self.hunter.required_source_files(self.args.static[0])
+                )
             recreateobjs = True
 
         if self.args.dynamic and len(self.args.dynamic) == 1:
-            self.args.dynamic.extend(
-                self.hunter.required_source_files(self.args.dynamic[0])
-            )
+            with compiletools.timing.time_operation("dynamic_source_hunting"):
+                self.args.dynamic.extend(
+                    self.hunter.required_source_files(self.args.dynamic[0])
+                )
             recreateobjs = True
 
         if self.args.auto:
-            findtargets = compiletools.findtargets.FindTargets(self.args)
-            findtargets.process(self.args)
+            with compiletools.timing.time_operation("target_detection"):
+                findtargets = compiletools.findtargets.FindTargets(self.args)
+                findtargets.process(self.args)
             recreateobjs = True
 
         if recreateobjs:
@@ -246,15 +251,18 @@ def process(self):
             # targets. And recreate the ct objects
             if self.args.verbose > 4:
                 print("Cake recreating objects and reparsing for second stage processing")
-            compiletools.apptools.substitutions(self.args, verbose=0)
-            self._createctobjs()
+            with compiletools.timing.time_operation("recreate_ct_objects"):
+                compiletools.apptools.substitutions(self.args, verbose=0)
+                self._createctobjs()
 
         compiletools.apptools.verboseprintconfig(self.args)
 
         if self.args.filelist:
-            self._callfilelist()
+            with compiletools.timing.time_operation("filelist_generation"):
+                self._callfilelist()
         else:
-            self._callmakefile()
+            with compiletools.timing.time_operation("makefile_creation_and_execution"):
+                self._callmakefile()
 
     def clear_cache(self):
         """ Only useful in test scenarios where you need to reset to a pristine state """
@@ -279,6 +287,10 @@ def main(argv=None):
 
     args = compiletools.apptools.parseargs(cap, argv)
 
+    # Initialize timing if enabled
+    timing_enabled = hasattr(args, 'time') and args.time
+    compiletools.timing.initialize_timer(timing_enabled)
+
     if not any([args.filename, args.static, args.dynamic, args.tests, args.auto]):
         print(
             "Nothing for cake to do.  Did you mean cake --auto? Use cake --help for help."
@@ -290,7 +302,8 @@ def main(argv=None):
 
     try:
         cake = Cake(args)
-        cake.process()
+        with compiletools.timing.time_operation("total_build_time"):
+            cake.process()
         # For testing purposes, clear out the memcaches for the times when main is called more than once.
         cake.clear_cache()
     except IOError as ioe:
@@ -305,5 +318,9 @@ def main(argv=None):
             return 1
         else:
             raise
+    
+    # Report timing information if enabled
+    if timing_enabled:
+        compiletools.timing.report_timing(args.verbose)
 
     return 0

src/compiletools/headerdeps.py

@@ -13,6 +13,7 @@
 from compiletools.diskcache import diskcache
 from compiletools.simple_preprocessor import SimplePreprocessor
 from compiletools.file_analyzer import create_file_analyzer
+import compiletools.timing
 
 
 
@@ -59,15 +60,16 @@ def _process_impl(self, realpath):
     def process(self, filename):
         """Return the set of dependencies for a given filename"""
         realpath = compiletools.wrappedos.realpath(filename)
-        try:
-            result = self._process_impl(realpath)
-        except IOError:
-            # If there was any error the first time around, an error correcting removal would have occured
-            # So strangely, the best thing to do is simply try again
-            result = None
+        with compiletools.timing.time_operation(f"header_dependency_analysis_{os.path.basename(filename)}"):
+            try:
+                result = self._process_impl(realpath)
+            except IOError:
+                # If there was any error the first time around, an error correcting removal would have occured
+                # So strangely, the best thing to do is simply try again
+                result = None
 
-        if not result:
-            result = self._process_impl(realpath)
+            if not result:
+                result = self._process_impl(realpath)
 
         return result
 
@@ -175,25 +177,29 @@ def _process_conditional_compilation(self, text):
     @functools.lru_cache(maxsize=None)
     def _create_include_list(self, realpath):
         """Internal use. Create the list of includes for the given file"""
-        max_read_size = getattr(self.args, 'max_file_read_size', 0)
-        
-        # Use FileAnalyzer for efficient file reading and pattern detection  
-        # Note: create_file_analyzer() handles StringZilla/Legacy fallback internally
-        from compiletools.file_analyzer import create_file_analyzer
-        analyzer = create_file_analyzer(realpath, max_read_size, self.args.verbose)
-        analysis_result = analyzer.analyze()
-        text = analysis_result.text
-
-        # Process conditional compilation - this updates self.defined_macros as it encounters #define
-        processed_text = self._process_conditional_compilation(text)
-
-        # The pattern is intended to match all include statements but
-        # not the ones with either C or C++ commented out.
-        pat = re.compile(
-            r'/\*.*?\*/|//.*?$|^[\s]*#include[\s]*["<][\s]*([\S]*)[\s]*[">]',
-            re.MULTILINE | re.DOTALL,
-        )
-        return [group for group in pat.findall(processed_text) if group]
+        with compiletools.timing.time_operation(f"include_analysis_{os.path.basename(realpath)}"):
+            max_read_size = getattr(self.args, 'max_file_read_size', 0)
+            
+            # Use FileAnalyzer for efficient file reading and pattern detection  
+            # Note: create_file_analyzer() handles StringZilla/Legacy fallback internally
+            from compiletools.file_analyzer import create_file_analyzer
+            with compiletools.timing.time_operation(f"file_read_{os.path.basename(realpath)}"):
+                analyzer = create_file_analyzer(realpath, max_read_size, self.args.verbose)
+                analysis_result = analyzer.analyze()
+                text = analysis_result.text
+
+            # Process conditional compilation - this updates self.defined_macros as it encounters #define
+            with compiletools.timing.time_operation(f"conditional_compilation_{os.path.basename(realpath)}"):
+                processed_text = self._process_conditional_compilation(text)
+
+            # The pattern is intended to match all include statements but
+            # not the ones with either C or C++ commented out.
+            with compiletools.timing.time_operation(f"pattern_matching_{os.path.basename(realpath)}"):
+                pat = re.compile(
+                    r'/\*.*?\*/|//.*?$|^[\s]*#include[\s]*["<][\s]*([\S]*)[\s]*[">]',
+                    re.MULTILINE | re.DOTALL,
+                )
+                return [group for group in pat.findall(processed_text) if group]
 
     def _generate_tree_impl(self, realpath, node=None):
         """Return a tree that describes the header includes

src/compiletools/magicflags.py

@@ -13,6 +13,7 @@
 import compiletools.configutils
 import compiletools.apptools
 from compiletools.file_analyzer import create_file_analyzer
+import compiletools.timing
 
 
 def create(args, headerdeps):
@@ -79,7 +80,8 @@ def readfile(self, filename):
         raise NotImplemented
 
     def __call__(self, filename):
-        return self.parse(filename)
+        with compiletools.timing.time_operation(f"magic_flags_analysis_{os.path.basename(filename)}"):
+            return self.parse(filename)
 
     def _handle_source(self, flag, text):
         # Find the include before the //#SOURCE=
@@ -160,43 +162,49 @@ def _parse(self, filename):
         # When used in the "usual" fashion this is true.
         # However, it is possible to call directly so we must
         # ensure that the headerdeps exist manually.
-        self._headerdeps.process(filename)
+        with compiletools.timing.time_operation(f"magic_flags_headerdeps_{os.path.basename(filename)}"):
+            self._headerdeps.process(filename)
 
-        text = self.readfile(filename)
-        flagsforfilename = defaultdict(list)
-
-        for match in self.magicpattern.finditer(text):
-            magic, flag = match.groups()
-
-            # If the magic was SOURCE then fix up the path in the flag
-            if magic == "SOURCE":
-                flag = self._handle_source(flag, text)
-
-            # If the magic was INCLUDE then modify that into the equivalent CPPFLAGS, CFLAGS, and CXXFLAGS
-            if magic == "INCLUDE":
-                extrafff = self._handle_include(flag)
-                for key, values in extrafff.items():
-                    for value in values:
-                        flagsforfilename[key].append(value)
-
-            # If the magic was PKG-CONFIG then call pkg-config
-            if magic == "PKG-CONFIG":
-                extrafff = self._handle_pkg_config(flag)
-                for key, values in extrafff.items():
-                    for value in values:
-                        flagsforfilename[key].append(value)
-
-            flagsforfilename[magic].append(flag)
-            if self._args.verbose >= 5:
-                print(
-                    "Using magic flag {0}={1} extracted from {2}".format(
-                        magic, flag, filename
-                    )
-                )
+        with compiletools.timing.time_operation(f"magic_flags_readfile_{os.path.basename(filename)}"):
+            text = self.readfile(filename)
 
-        # Deduplicate all flags while preserving order
-        for key in flagsforfilename:
-            flagsforfilename[key] = compiletools.utils.ordered_unique(flagsforfilename[key])
+        with compiletools.timing.time_operation(f"magic_flags_parsing_{os.path.basename(filename)}"):
+            flagsforfilename = defaultdict(list)
+
+            for match in self.magicpattern.finditer(text):
+                magic, flag = match.groups()
+
+                # If the magic was SOURCE then fix up the path in the flag
+                if magic == "SOURCE":
+                    flag = self._handle_source(flag, text)
+
+                # If the magic was INCLUDE then modify that into the equivalent CPPFLAGS, CFLAGS, and CXXFLAGS
+                if magic == "INCLUDE":
+                    with compiletools.timing.time_operation(f"magic_flags_include_handling_{flag}"):
+                        extrafff = self._handle_include(flag)
+                        for key, values in extrafff.items():
+                            for value in values:
+                                flagsforfilename[key].append(value)
+
+                # If the magic was PKG-CONFIG then call pkg-config
+                if magic == "PKG-CONFIG":
+                    with compiletools.timing.time_operation(f"magic_flags_pkgconfig_{flag}"):
+                        extrafff = self._handle_pkg_config(flag)
+                        for key, values in extrafff.items():
+                            for value in values:
+                                flagsforfilename[key].append(value)
+
+                flagsforfilename[magic].append(flag)
+                if self._args.verbose >= 5:
+                    print(
+                        "Using magic flag {0}={1} extracted from {2}".format(
+                            magic, flag, filename
+                        )
+                    )
+            
+            # Deduplicate all flags while preserving order
+            for key in flagsforfilename:
+                flagsforfilename[key] = compiletools.utils.ordered_unique(flagsforfilename[key])
 
         return flagsforfilename
 

src/compiletools/makefile.py

@@ -13,6 +13,7 @@
 import compiletools.hunter
 import compiletools.namer
 import compiletools.configutils
+import compiletools.timing
 
 
 class Rule:
@@ -110,9 +111,24 @@ def _create_link_rule(
                 all_magic_ldflags.extend(magic_flags.get("LINKFLAGS", []))  # For backward compatibility with cake
             all_magic_ldflags = compiletools.utils.ordered_unique(all_magic_ldflags)
         recipe = ""
-        if self.args.verbose >= 1:
+        
+        # Add timing for link operations if enabled
+        link_timing_prefix = ""
+        link_timing_suffix = ""
+        if hasattr(self.args, 'time') and self.args.time and self.args.verbose >= 1:
+            link_timing_prefix = "@START=$$(date +%s%N); "
+            link_timing_suffix = f"; END=$$(date +%s%N); echo \"... linking {outputname} ($$(( ($$END-$$START)/1000000 ))ms)\""
+        
+        if self.args.verbose >= 1 and not (hasattr(self.args, 'time') and self.args.time):
             recipe += " ".join(["+@echo ...", outputname, ";"])
-        recipe += " ".join([linker, "-o", outputname] + list(object_names) + list(all_magic_ldflags) + [linkerflags])
+        
+        link_flags = [linker, "-o", outputname] + list(object_names) + list(all_magic_ldflags) + [linkerflags]
+        if hasattr(self.args, 'time') and self.args.time and self.args.verbose >= 3:
+            # Add -time flag for detailed linker timing
+            link_flags.insert(1, "-time")
+        
+        link_cmd = " ".join(link_flags)
+        recipe += link_timing_prefix + link_cmd + link_timing_suffix
         return Rule(target=outputname, prerequisites=allprerequisites, recipe=recipe)
 
 
@@ -561,19 +577,34 @@ def _create_compile_rule_for_source(self, filename):
 
         magicflags = self.hunter.magicflags(filename)
         recipe = ""
-        if self.args.verbose >= 1:
+        
+        # Add timing wrapper if enabled
+        timing_prefix = ""
+        timing_suffix = ""
+        if hasattr(self.args, 'time') and self.args.time and self.args.verbose >= 1:
+            # Simple timing with elapsed time display
+            timing_prefix = "@START=$$(date +%s%N); "
+            timing_suffix = f"; END=$$(date +%s%N); echo \"... {filename} ($$(( ($$END-$$START)/1000000 ))ms)\""
+        
+        if self.args.verbose >= 1 and not (hasattr(self.args, 'time') and self.args.time):
             recipe = " ".join(["@echo ...", filename, ";"])
+        
         magic_cpp_flags = magicflags.get("CPPFLAGS", [])
+        compile_cmd = ""
         if compiletools.wrappedos.isc(filename):
             magic_c_flags = magicflags.get("CFLAGS", [])
-            recipe += " ".join(
-                [self.args.CC, self.args.CFLAGS] + list(magic_cpp_flags) + list(magic_c_flags) + ["-c", "-o", obj_name, filename]
-            )
+            compile_flags = [self.args.CC, self.args.CFLAGS] + list(magic_cpp_flags) + list(magic_c_flags)
+            if hasattr(self.args, 'time') and self.args.time and self.args.verbose >= 3:
+                compile_flags.append("-time")
+            compile_cmd = " ".join(compile_flags + ["-c", "-o", obj_name, filename])
         else:
             magic_cxx_flags = magicflags.get("CXXFLAGS", [])
-            recipe += " ".join(
-                [self.args.CXX, self.args.CXXFLAGS] + list(magic_cpp_flags) + list(magic_cxx_flags) + ["-c", "-o", obj_name, filename]
-            )
+            compile_flags = [self.args.CXX, self.args.CXXFLAGS] + list(magic_cpp_flags) + list(magic_cxx_flags)
+            if hasattr(self.args, 'time') and self.args.time and self.args.verbose >= 3:
+                compile_flags.append("-time")
+            compile_cmd = " ".join(compile_flags + ["-c", "-o", obj_name, filename])
+        
+        recipe += timing_prefix + compile_cmd + timing_suffix
 
         if self.args.verbose >= 3:
             print("Creating rule for ", obj_name)