Andrew Fish [mailto:[email protected]] wrote:
]Sent: Friday, October 23, 2015 06:12 PM ]To: edk2-devel-01 <[email protected]> ]Subject: [edk2] [BaseTools] I see main Python thread of build doing acquire thread.lock 87% of a single ]threaded build. ] ]I was playing around with turning on cProfile for the Python build and I noticed 87% of the time is spent in ]acquire, and I assume that means the main thread is blocking on another thread? Is this expected? Does any ]one know how to turn on profiling for the other threads? ] ]Is it possible to get data like this out of the Python on Windows to compare? ] ]>build -p MdeModulePkg/MdeModulePkg.dsc -a X64 -t XCODE5 -n 1 ]... ] 13095719 function calls (12877055 primitive calls) in 81.637 seconds ] ] Ordered by: internal time ] ] ncalls tottime percall cumtime percall filename:lineno(function) ] 282 70.976 0.252 70.976 0.252 {method 'acquire' of 'thread.lock' objects} ] 96937 1.764 0.000 1.764 0.000 {method 'findall' of '_sre.SRE_Pattern' objects} ] 865464 0.560 0.000 0.859 0.000 Misc.py:1786(__eq__) ] 9932 0.519 0.000 0.519 0.000 {method 'execute' of 'sqlite3.Cursor' objects} ] 92418 0.436 0.000 0.727 0.000 posixpath.py:329(normpath) ] 1719 0.241 0.000 0.440 0.000 InfSectionParser.py:28(_ParserInf) ] 2189713 0.226 0.000 0.226 0.000 {method 'append' of 'list' objects} ] 790 0.223 0.000 2.552 0.003 GenMake.py:742(GetDependencyList) ] 434757 0.202 0.000 0.624 0.000 BuildClassObject.py:219(__eq__) ] 109832 0.180 0.000 0.421 0.000 build.py:354(__eq__) ] 1 0.171 0.171 0.211 0.211 ToolDefClassObject.py:60(LoadToolDefFile) ] 41009 0.164 0.000 0.164 0.000 {posix.stat} ] 24909 0.140 0.000 0.543 0.000 Misc.py:1719(__init__) ] 295151 0.136 0.000 0.136 0.000 {method 'split' of 'str' objects} ] 649508 0.132 0.000 0.132 0.000 {method 'startswith' of 'str' objects} ] 215491 0.123 0.000 0.157 0.000 AutoGen.py:202(__str__) ] 455332 0.120 0.000 0.157 0.000 Misc.py:1819(__hash__) ] 100920 0.119 0.000 0.169 0.000 StringIO.py:208(write) ] 25519 0.114 0.000 0.236 0.000 GenMake.py:206(PlaceMacro) ] 20198 0.111 0.000 0.147 0.000 Misc.py:881(Instantiate) ] 214334 0.111 0.000 0.145 0.000 BuildClassObject.py:209(__str__) ] 215830 0.111 0.000 0.448 0.000 AutoGen.py:206(__eq__) ] 260151 0.108 0.000 0.248 0.000 UserDict.py:18(__getitem__) ] 59129 0.101 0.000 0.515 0.000 Misc.py:1104(__contains__) ] ]Also is findall being called too much? ] ]Thanks, ] ]Andrew Fish Hello Andrew, I can't answer your questions easily, but I can do a Windows run... >build -p MdeModulePkg/MdeModulePkg.dsc -a X64 -t VS2010x86 -n 1 ... Build total time: 00:01:44 13531956 function calls (13317330 primitive calls) in 104.252 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 274 93.397 0.341 93.397 0.341 {method 'acquire' of 'thread.lock' objects} 96944 1.478 0.000 1.478 0.000 {method 'findall' of '_sre.SRE_Pattern' objects} 9934 0.782 0.000 0.782 0.000 {method 'execute' of 'sqlite3.Cursor' objects} 40657 0.552 0.000 0.552 0.000 {nt.stat} 871094 0.480 0.000 0.712 0.000 Misc.py:1786(__eq__) 92107 0.445 0.000 0.715 0.000 ntpath.py:398(normpath) 1719 0.223 0.000 0.394 0.000 InfSectionParser.py:28(_ParserInf) 1136 0.221 0.000 0.221 0.000 {Common.PyUtility.SaveFileToDisk} 1 0.207 0.207 0.252 0.252 ToolDefClassObject.py:60(LoadToolDefFile) 863 0.203 0.000 2.970 0.003 GenMake.py:742(GetDependencyList) 433420 0.169 0.000 0.525 0.000 BuildClassObject.py:219(__eq__) 347689 0.146 0.000 0.146 0.000 {method 'split' of 'str' objects} 109832 0.138 0.000 0.327 0.000 build.py:356(__eq__) 479 0.134 0.000 0.324 0.001 MetaFileTable.py:229(GetValidExpression) 1791 0.117 0.000 0.117 0.000 {method 'read' of 'file' objects} 96659 0.117 0.000 0.186 0.000 ntpath.py:63(join) 25060 0.111 0.000 0.583 0.000 Misc.py:1719(__init__) 3791 0.110 0.000 0.110 0.000 {open} 615806 0.101 0.000 0.101 0.000 {method 'startswith' of 'str' objects} Thanks, Scott ]PS This is how I turned on cProfile ] ]~/work/src/edk2(master)>git diff BaseTools/BinWrappers/PosixLike/build ]diff --git a/BaseTools/BinWrappers/PosixLike/build b/BaseTools/BinWrappers/PosixLike/build ]index 2cb8b86..1115da7 100755 ]--- a/BaseTools/BinWrappers/PosixLike/build ]+++ b/BaseTools/BinWrappers/PosixLike/build ]@@ -1,5 +1,5 @@ ] #!/usr/bin/env bash ] #python `dirname $0`/RunToolFromSource.py `basename $0` $* ] PYTHONPATH="`dirname $0`/../../Source/Python" \ ]- python "`dirname $0`/../../Source/Python"/`basename $0`/`basename $0`.py $* ]+ python -m cProfile -s time "`dirname $0`/../../Source/Python"/`basename $0`/`basename $0`.py $* ] _______________________________________________ edk2-devel mailing list [email protected] https://lists.01.org/mailman/listinfo/edk2-devel
