Perl profiling笔记

项目背景

 

在一个庞大的代码自动生成项目中，需要通过对C/C++头文件的扫描分析并记录所有public类型的函数原型及参数类型。

在XML script中，显式使用C函数和参数。用户可以自行编写xml测试脚本来运行C/C++代码。

上述过程都通过perl script自动生成并编译。

 

问题

 

自动生成代码量巨大，很大部分的时间瓶颈在于perl脚本的执行时间。需要进行优化。

 

方法

 

利用了perl的profiling机制进行运行时profiling分析并分perl函数统计所有时间开销。

最后重点改善耗费时间最多的20-30个瓶颈函数。

 

结果

 

不包括makefile等方面的脚本编译优化，不考虑perl脚本的功能实现大变动，perl执行时间有大约10~15%的提升。

 

-------------------------------------------------------------------------------------------------------------------------------------------------------------

 

了解速度瓶颈

• perl -d:DProf test.pl
  • Perl dprofpp 显示perl的概要设置数据。
  • Devel::DProf运行时增加-d:DProf选项，会自动生成一个tmon.out文件
  • 查看profile结果，运行dprof

 

典型的，tmon.out示例如下

#fOrTyTwO
$hz=1000;
$XS_VERSION='DProf 20050310.00';
# All values are given in HZ
$over_utime=32; $over_stime=0; $over_rtime=32;
$over_tests=10000;
$rrun_utime=15; $rrun_stime=0; $rrun_rtime=15;
$total_marks=2                                                                                                                                                                                   

PART2
@ 15 0 15
& 2 main BEGIN
+ 2
- 2

 

对于perl脚本执行后产生的profiling概要数据示例如下

Total Elapsed Time = 0.139411 Seconds
  User+System Time = 0.061411 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 26.0   0.016  0.016      1   0.0160 0.0160  warnings::BEGIN
 26.0   0.016  0.016      1   0.0160 0.0160  fileutils::RemoveFilesWithContent
 24.4   0.015  0.015      6   0.0025 0.0025  FindBin::BEGIN
 24.4   0.015  0.045      7   0.0021 0.0065  main::BEGIN
 0.00       - -0.000      1        -      -  File::Basename::fileparse_set_fsty
                                     0.0000  pe
 0.00       - -0.000      1        -      -  lib::_nativize
 0.00       - -0.000      1        -      -  Getopt::Long::ConfigDefaults
 0.00       - -0.000      1        -      -  Getopt::Long::Configure
 0.00       - -0.000      1        -      -  DynaLoader::dl_load_file
 0.00       - -0.000      1        -      -  DynaLoader::dl_undef_symbols
 0.00       - -0.000      1        -      -  DynaLoader::dl_find_symbol
 0.00       - -0.000      1        -      -  DynaLoader::dl_install_xsub
 0.00       - -0.000      1        -      -  Cwd::bootstrap
 0.00       - -0.000      1        -      -  Config::TIEHASH
 0.00       - -0.000      1        -      -  re::bits

perl执行时间统计结果示例

======    Final Data Result in Values order ( Time Unit: second)  ======

134.68317	<=	all_total_elapsed_time
83.519373	<=	all_user_system_time
42.560276	<=	genentityfile.pl::total_elapsed_time
24.133051	<=	genapiids.pl::total_elapsed_time
18.171	<=	main::BEGIN
16.265623	<=	genapinamesfromtemplate.pl::total_elapsed_time
15.991419	<=	genapinamesfromtemplate.pl::user_system_time
10.250529	<=	genentityfile.pl::user_system_time
10.030177	<=	genmoduleapifiles.pl::total_elapsed_time
9.902177	<=	genmoduleapifiles.pl::user_system_time
8.354992	<=	genscriptschema.pl::total_elapsed_time
8.294992	<=	genscriptschema.pl::user_system_time
7.45852	<=	genmoduleversionfile.pl::total_elapsed_time
7.417362	<=	genapiids.pl::user_system_time
7.36752	<=	genmoduleversionfile.pl::user_system_time
7.227387	<=	convertxscriptapis.pl::total_elapsed_time
7.136385	<=	convertxscriptapis.pl::user_system_time
6.909191	<=	genatsfile.pl::total_elapsed_time
6.868048	<=	genatsfile.pl::user_system_time
5.80599999999999	<=	debugutils::BEGIN
5.69099999999999	<=	IO::File
5.67999999999999	<=	File::Temp
4.112021	<=	compilescript.pl::total_elapsed_time
4.112	<=	FindBin::BEGIN
4.09702	<=	compilescript.pl::user_system_time
3.639	<=	tmpfile::BEGIN
3.589	<=	templateparser::BEGIN
3.19	<=	datamanager::BEGIN
3.089	<=	IO::Seekable
2.902	<=	Benchmark::BEGIN
2.451	<=	templateparser::ReplaceNameValuePa
2.403	<=	vars::BEGIN
2.24	<=	Getopt::Long
2.159	<=	enumparser::ParseEnumFile
1.867215	<=	geneventhandlerfromtemplate.pl::total_elapsed_time
1.867205	<=	geneventhandlerfromtemplate.pl::user_system_time
1.609	<=	IO::Handle
1.387	<=	Exporter::as_heavy
1.35	<=	apisparser::ParseAPIs
1.295	<=	warnings::BEGIN
1.133	<=	DynaLoader::dl_load_file
1.05	<=	configparser::BEGIN
0.943427	<=	genfilefromtemplate.pl::total_elapsed_time
0.908427	<=	genfilefromtemplate.pl::user_system_time
0.846000000000001	<=	cpreprocessfile::PreprocessFile
0.827000000000001	<=	File::Basename
0.809	<=	Exporter::import
0.798000000000001	<=	apisparser::BEGIN
0.74	<=	calculatecrc::CRC16_CalculateCRC
0.729000000000001	<=	scriptapiparser::BEGIN
0.690000000000001	<=	DynaLoader::bootstrap
0.681	<=	vars::import
0.642	<=	eventsparser::ParseEvents
0.598	<=	Storable::BEGIN
0.573	<=	templateparser::StripSubstringForI
0.560688	<=	genglobalrefsfromtemplate.pl::user_system_time
0.559688	<=	genglobalrefsfromtemplate.pl::total_elapsed_time
0.532	<=	enumparser::BEGIN
0.482	<=	XSLoader::load
0.471	<=	AutoLoader::AUTOLOAD
0.465705	<=	findfiles.pl::total_elapsed_time
0.436	<=	Cwd::fast_abs_path
0.41	<=	templateparser::PreserveSubstringF
0.392	<=	apideffileparser::GetGlobalsForMod
0.389	<=	enumparser::GetDigitValue
0.368973	<=	genentityversionfile.pl::total_elapsed_time
0.368973	<=	genentityversionfile.pl::user_system_time
0.357	<=	isiconfigparser::BEGIN
0.353	<=	debugutils::DebugPrint
0.343	<=	lib::import
0.331	<=	Storable::pretrieve
0.303	<=	apisparser::GetParentStructureName
0.295134	<=	genxmlmultiinput.pl::total_elapsed_time
0.285	<=	apisparser::GetNamespaceFromApiIDS
0.279134	<=	genxmlmultiinput.pl::user_system_time
0.279	<=	File::Copy
0.277984	<=	genadaptergroups.pl::total_elapsed_time
0.277984	<=	genadaptergroups.pl::user_system_time
0.255	<=	apisparser::GetStructsFromLine
0.24919	<=	SCRIPTS_LISTS_DIAG::total_elapsed_time
0.231705	<=	findfiles.pl::user_system_time
0.231	<=	templateparser::ProcessTemplate
0.219	<=	cpreprocessfile::StripPreprocessor
0.217	<=	constant::import
0.215	<=	validateparams::ValidatePos
0.207	<=	warnings::register
0.206	<=	entityparser::ParseEntityFile
0.204	<=	cpreprocessfile::BEGIN
0.188	<=	File::stat
0.187	<=	moduleidsparser::BEGIN
0.173	<=	storabledata::BEGIN
0.171205	<=	SCRIPTS_INC_SRCS_DIAG::total_elapsed_time
0.147	<=	templateparser::ReplaceIfCondition
0.141	<=	main::WriteFileContents_NoXmlVersi
0.138	<=	adaptercodegen::WriteForAPI
0.131	<=	apisparser::IsParamNotScriptableBy
0.124	<=	main::WriteFile_NoXmlVersion
0.124	<=	scriptcompiler::BEGIN
0.123	<=	FindBin::init
0.11	<=	main::WriteData
0.10843	<=	getxscriptversion.pl::total_elapsed_time
0.105502	<=	geneventhandlerfactoryfromtemplate.pl::user_system_time
0.105502	<=	geneventhandlerfactoryfromtemplate.pl::total_elapsed_time
0.104	<=	scriptapiparser::GetCppClassNames
0.099	<=	templateparser::StripSubstring
0.095	<=	tmpfile::DeleteTmpFile
0.093205	<=	SCRIPTS_INC_SRCS_DIAG::user_system_time
0.093	<=	File::Spec
0.09219	<=	SCRIPTS_LISTS_DIAG::user_system_time
0.085	<=	enumparser::GetEnumValueFromMaps
0.083	<=	main::WriteForEachEntityFile
0.08	<=	AutoLoader::import
0.079	<=	datamanager::OutputNameValuePair
0.079	<=	main::WriteDefs
0.079	<=	strict::unimport
0.078	<=	scriptapiparser::GetModuleList
0.078	<=	main::ProcessXml
0.076	<=	pounddefineparser::ParseDefinesFil
0.074	<=	templateparser::CreateEnumNameFrom
0.074	<=	templateparser::PreserveSubstring
0.073	<=	main::WriteVersions
0.07	<=	Regexp::DESTROY
0.063	<=	main::EnumGroupCallback
0.063	<=	Storable::bootstrap
0.063	<=	DynaLoader::dl_install_xsub
0.062	<=	strict::import
0.062	<=	datamanager::WriteSetNameValuePair
0.06143	<=	getxscriptversion.pl::user_system_time
0.061	<=	Class::Struct
0.06	<=	IO::bootstrap
0.047	<=	warnings::import
0.047	<=	eventhandlerparser::BEGIN
0.047	<=	err::BEGIN
0.047	<=	main::GetGlobalVariableList
0.046	<=	main::WriteScriptSymbolsForAPI
0.046	<=	datamanager::WriteField
0.046	<=	strict::bits
0.046	<=	overload::OVERLOAD
0.046	<=	enumparser::ParseEnumFileWithPrepr
0.046	<=	apisparser::ReplaceXmlEntitiesInCp
0.046	<=	scriptapiparser::ConvertScriptFile
0.046	<=	eventhandlerparser::GetEventHandle
0.045	<=	Time::HiRes
0.045	<=	datamanager::ResolveFieldName
0.032	<=	enumpreserver::GetExistingEnumValu
0.031	<=	main::WriteSchemaForLoopCB
0.031	<=	adaptercodegen::WriteHandleResultF
0.031	<=	main::WriteEntityParamIDsForAPI
0.031	<=	fileutils::BEGIN
0.031	<=	apisparser::GetArgsArray
0.031	<=	fileutils::ExecShellFindCmd
0.031	<=	templateparser::WriteForEachInclud
0.031	<=	apisparser::HasFieldsWithUseType
0.031	<=	Fcntl::constant
0.031	<=	datamanager::OpenIfs
0.031	<=	main::WriteDefsParamsForAPI
0.03	<=	apisparser::IsArrayElement
0.016	<=	main::WriteFunctionDefsForAPI
0.016	<=	main::GetModuleSchemaFileName
0.016	<=	apisparser::GetReturnName
0.016	<=	Fcntl::AUTOLOAD
0.016	<=	re::import
0.016	<=	datamanager::ConvertToDataMgrEntit
0.016	<=	Symbol::gensym
0.016	<=	main::WriteEntitiesForEvent
0.016	<=	versionparser::BEGIN
0.016	<=	validateparams::BEGIN
0.016	<=	SelectSaver::new
0.016	<=	datamanager::GenPtrStructCppExpr
0.016	<=	storabledata::GetDataForPhase3
0.016	<=	enumparser::CallEnumGroupCallback
0.016	<=	apisparser::IsDescendant
0.016	<=	Config::import
0.016	<=	validateparams::Validate
0.016	<=	apisparser::GetDataItemFromList
0.016	<=	main::WriteOutputEntitiesForAPI
0.016	<=	main::CompileScript
0.016	<=	main::GetApisForModule
0.016	<=	eventsparser::GetPayloadNameAndTyp
0.016	<=	main::WriteAtsForLoopCB
0.016	<=	Benchmark::init
0.016	<=	Storable::_retrieve
0.016	<=	enumpreserver::CopyFileUntilEndMar
0.016	<=	apisparser::GetParam
0.015	<=	fileutils::RemoveFilesWithContent
0.015	<=	main::WriteFooterForSchema
0.015	<=	AutoLoader::BEGIN
0.015	<=	IO::BEGIN
0.015	<=	apisparser::IsUnionOrVoidPtrDescen
0.015	<=	main::WriteSchemaForAPI
0.015	<=	datamanager::GetClosestAncestorStr
0.015	<=	datamanager::CloseForLoops
0.015	<=	Cwd::cwd
0.015	<=	scriptapiparser::GetApiFromScriptL
0.015	<=	main::WriteDataParamsForAPI
0.015	<=	enumpreserver::WriteEnum
0.015	<=	base::has_version
7.9e-05	<=	convertmoduleids.pl::total_elapsed_time
7.8e-05	<=	convertmoduleids.pl::user_system_time
0	<=	Storable::_store
0	<=	Exporter::Heavy
0	<=	Storable::retrieve
0	<=	Storable::store
0	<=	Fcntl::__ANON__