Python imports take time too, so record toolchain profiler process starts before the imports take place. Also filter out multiple process start and finish records, which is simplest to do in the toolchain_profiler side rather than strictly tracking on the caller side.

em++

@@ -10,9 +10,9 @@ import sys
 sys.argv += ['--emscripten-cxx']
 
 if sys.version_info.major == 2:
-  import emcc
   if __name__ == '__main__':
     ToolchainProfiler.record_process_start()
+    import emcc
     emcc.run()
     sys.exit(0)
 else:

emar

@@ -7,9 +7,9 @@ from tools.toolchain_profiler import ToolchainProfiler
 import sys
 
 if sys.version_info.major == 2:
-  import emar
   if __name__ == '__main__':
     ToolchainProfiler.record_process_start()
+    import emar
     emar.run()
     sys.exit(0)
 else:

emar.py

@@ -8,6 +8,8 @@ This script acts as a frontend replacement for ar. See emcc.
 '''
 
 from tools.toolchain_profiler import ToolchainProfiler
+if __name__ == '__main__':
+  ToolchainProfiler.record_process_start()
 
 import os, subprocess, sys
 from tools import shared
@@ -61,6 +63,5 @@ def run():
       shared.try_delete(d)
 
 if __name__ == '__main__':
-  ToolchainProfiler.record_process_start()
   run()
   sys.exit(0)

emcc

@@ -7,9 +7,9 @@ from tools.toolchain_profiler import ToolchainProfiler
 import sys
 
 if sys.version_info.major == 2:
-  import emcc
   if __name__ == '__main__':
     ToolchainProfiler.record_process_start()
+    import emcc
     emcc.run()
     sys.exit(0)
 else:

emmake

@@ -9,9 +9,9 @@ import sys
 
 
 if sys.version_info.major == 2:
-  import emmake
   if __name__ == '__main__':
     ToolchainProfiler.record_process_start()
+    import emmake
     emmake.run()
     sys.exit(0)
 else:

tools/toolchain_profiler.py

@@ -80,6 +80,13 @@ if EM_PROFILE_TOOLCHAIN:
     imaginary_pid_ = 0
     profiler_logs_path = None # Log file not opened yet
 
+    block_stack = []
+
+    # Because process spawns are tracked from multiple entry points, it is possible that record_process_start() and/or record_process_exit()
+    # are called multiple times. Prevent recording multiple entries to the logs to keep them clean.
+    process_start_recorded = False
+    process_exit_recorded = False
+
     @staticmethod
     def timestamp():
       return '{0:.3f}'.format(time.time())
@@ -99,6 +106,9 @@ if EM_PROFILE_TOOLCHAIN:
 
     @staticmethod
     def record_process_start(write_log_entry=True):
+      if ToolchainProfiler.process_start_recorded: return
+      ToolchainProfiler.process_start_recorded = True
+
       ToolchainProfiler.block_stack = []
       # For subprocessing.Pool.map() child processes, this points to the PID of the parent process that spawned
       # the subprocesses. This makes the subprocesses look as if the parent had called the functions.
@@ -110,15 +120,16 @@ if EM_PROFILE_TOOLCHAIN:
         pass
       if write_log_entry:
         with ToolchainProfiler.log_access() as f:
-          f.write('[\n')
-          f.write('{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"start","time":' + ToolchainProfiler.timestamp() + ',"cmdLine":["' + '","'.join(sys.argv).replace('\\', '\\\\') + '"]}')
+          f.write('[\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"start","time":' + ToolchainProfiler.timestamp() + ',"cmdLine":["' + '","'.join(sys.argv).replace('\\', '\\\\') + '"]}')
 
     @staticmethod
     def record_process_exit(returncode):
+      if ToolchainProfiler.process_exit_recorded: return
+      ToolchainProfiler.process_exit_recorded = True
+
       ToolchainProfiler.exit_all_blocks()
       with ToolchainProfiler.log_access() as f:
-        f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"exit","time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}')
-        f.write('\n]\n')
+        f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"exit","time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}\n]\n')
 
     @staticmethod
     def record_subprocess_spawn(process_pid, process_cmdline):
@@ -135,8 +146,6 @@ if EM_PROFILE_TOOLCHAIN:
       with ToolchainProfiler.log_access() as f:
         f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"finish","targetPid":' + str(process_pid) + ',"time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}')
 
-    block_stack = []
-
     @staticmethod
     def enter_block(block_name):
       with ToolchainProfiler.log_access() as f: