From: Frank C. <fra...@ho...> - 2011-04-26 10:23:53
|
Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, opcontrol --shutdown opcontrol --callgraph=7 opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe opcontrol --start /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run opcontrol --dump opreport -c > profile_info.txt or opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so I obtain the following warning: warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so Either this is the wrong binary or the binary has been modified since the sample file was created. warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. |
From: Maynard J. <may...@us...> - 2011-04-26 19:17:41
|
Frank Chang wrote: > > Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, > > opcontrol --shutdown > opcontrol --callgraph=7 > opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe > opcontrol --start > > /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run > > > opcontrol --dump > opreport -c > profile_info.txt > or > opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > > I obtain the following warning: > warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > Either this is the wrong binary or the binary has been modified since the sample file was created. > warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe > > I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. Frank, I don't see an 'opcontrol --reset' above in your sequence of commands, so if you've run this sequence more than once, then you'll have sample data from multiple profile runs in oprofile's sample database. And very likely, some of the older sample data was from an older version of libmdMatchup.so. A couple tips: - Use '--separate=lib' option as it helps match up library samples with your executable - Start simple; set --callgraph=0 and --image=none. Once you have the basics running and you understand what you're seeing in the reports that opreport generates, then play with the various options. -Maynard > > > > > ------------------------------------------------------------------------------ > WhatsUp Gold - Download Free Network Management Software > The most intuitive, comprehensive, and cost-effective network > management toolset available today. Delivers lowest initial > acquisition cost and overall TCO of any competing solution. > http://p.sf.net/sfu/whatsupgold-sd > > > > _______________________________________________ > oprofile-list mailing list > opr...@li... > https://lists.sourceforge.net/lists/listinfo/oprofile-list |
From: Frank C. <fra...@ho...> - 2011-04-26 23:40:45
|
Maynard Johnson, Thank you for your reply. Your suggestions were very useful. We were wondering when we run : opcontrol --separate=library . We tried running opcontrol --separate=library before opcontrol --start and after opcontrol --start. In either case, we are obtaining the warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so Either this is the wrong binary or the binary has been modified since the sample file was created. So we decided to remove the /var/lib/oprofile/samples subdirectory and use opcontrol --reset. Now , we are no longer obtaining any warning messages. My supervisor asked me if oprofile could annotate source code. So I tried the command: opannotate --source --output-dir=/home/frankc/src/annotated ./Mary15.exe. When I looked in /home/frankc/src/annotated/..... I observed that certain cpp and hpp files were annotated with profiling measurements. I am just a newbie to oprofile. I was wondering where I could find information about oprofile source annotation. Thank you. > Date: Tue, 26 Apr 2011 14:16:59 -0500 > From: may...@us... > To: fra...@ho... > CC: opr...@li... > Subject: Re: oprofile on Centos Linux 5.5 > > Frank Chang wrote: > > > > Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, > > > > opcontrol --shutdown > > opcontrol --callgraph=7 > > opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe > > opcontrol --start > > > > /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run > > > > > > opcontrol --dump > > opreport -c > profile_info.txt > > or > > opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > > > > I obtain the following warning: > > warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > > Either this is the wrong binary or the binary has been modified since the sample file was created. > > warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe > > > > I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. > > Frank, > I don't see an 'opcontrol --reset' above in your sequence of commands, so if you've run this sequence more than once, then you'll have sample data from multiple profile runs in oprofile's sample database. And very likely, some of the older sample data was from an older version of libmdMatchup.so. > > A couple tips: > - Use '--separate=lib' option as it helps match up library samples with your executable > - Start simple; set --callgraph=0 and --image=none. Once you have the basics running and you understand what you're seeing in the reports that opreport generates, then play with the various options. > > -Maynard > > > > > > > > > > ------------------------------------------------------------------------------ > > WhatsUp Gold - Download Free Network Management Software > > The most intuitive, comprehensive, and cost-effective network > > management toolset available today. Delivers lowest initial > > acquisition cost and overall TCO of any competing solution. > > http://p.sf.net/sfu/whatsupgold-sd > > > > > > > > _______________________________________________ > > oprofile-list mailing list > > opr...@li... > > https://lists.sourceforge.net/lists/listinfo/oprofile-list > |
From: Maynard J. <may...@us...> - 2011-04-26 23:44:18
|
Frank Chang wrote: > > Maynard Johnson, Thank you for your reply. Your suggestions were very useful. We were wondering when we run : opcontrol --separate=library . We tried running opcontrol --separate=library before opcontrol --start and after opcontrol --start. In either case, > we are obtaining the warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > Either this is the wrong binary or the binary has been modified since the sample file was created. > So we decided to remove the /var/lib/oprofile/samples subdirectory and use opcontrol --reset. Now , we are no longer obtaining any warning messages. > My supervisor asked me if oprofile could annotate source code. So I tried the command: opannotate --source --output-dir=/home/frankc/src/annotated ./Mary15.exe. When I looked in /home/frankc/src/annotated/..... I observed that certain cpp and hpp files were annotated with profiling measurements. I am just a newbie to oprofile. I was wondering where I could find information about oprofile source annotation. Thank you. Frank, See http://oprofile.sourceforge.net/doc/opannotate.html. -Maynard > > >> Date: Tue, 26 Apr 2011 14:16:59 -0500 >> From: may...@us... >> To: fra...@ho... >> CC: opr...@li... >> Subject: Re: oprofile on Centos Linux 5.5 >> >> Frank Chang wrote: >>> >>> Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, >>> >>> opcontrol --shutdown >>> opcontrol --callgraph=7 >>> opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe >>> opcontrol --start >>> >>> /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run >>> >>> >>> opcontrol --dump >>> opreport -c > profile_info.txt >>> or >>> opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so >>> >>> I obtain the following warning: >>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so >>> Either this is the wrong binary or the binary has been modified since the sample file was created. >>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe >>> >>> I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. >> >> Frank, >> I don't see an 'opcontrol --reset' above in your sequence of commands, so if you've run this sequence more than once, then you'll have sample data from multiple profile runs in oprofile's sample database. And very likely, some of the older sample data was from an older version of libmdMatchup.so. >> >> A couple tips: >> - Use '--separate=lib' option as it helps match up library samples with your executable >> - Start simple; set --callgraph=0 and --image=none. Once you have the basics running and you understand what you're seeing in the reports that opreport generates, then play with the various options. >> >> -Maynard >>> >>> >>> >>> >>> ------------------------------------------------------------------------------ >>> WhatsUp Gold - Download Free Network Management Software >>> The most intuitive, comprehensive, and cost-effective network >>> management toolset available today. Delivers lowest initial >>> acquisition cost and overall TCO of any competing solution. >>> http://p.sf.net/sfu/whatsupgold-sd >>> >>> >>> >>> _______________________________________________ >>> oprofile-list mailing list >>> opr...@li... >>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >> > |
From: Frank C. <fra...@ho...> - 2011-04-27 05:23:23
|
Maynard Johnson, Thank you for you help. We hope to use oprofile throughout our company. > Date: Tue, 26 Apr 2011 18:44:20 -0500 > From: may...@us... > To: fra...@ho... > CC: opr...@li... > Subject: Re: oprofile on Centos Linux 5.5 > > Frank Chang wrote: > > > > Maynard Johnson, Thank you for your reply. Your suggestions were very useful. We were wondering when we run : opcontrol --separate=library . We tried running opcontrol --separate=library before opcontrol --start and after opcontrol --start. In either case, > > we are obtaining the warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > > Either this is the wrong binary or the binary has been modified since the sample file was created. > > So we decided to remove the /var/lib/oprofile/samples subdirectory and use opcontrol --reset. Now , we are no longer obtaining any warning messages. > > My supervisor asked me if oprofile could annotate source code. So I tried the command: opannotate --source --output-dir=/home/frankc/src/annotated ./Mary15.exe. When I looked in /home/frankc/src/annotated/..... I observed that certain cpp and hpp files were annotated with profiling measurements. I am just a newbie to oprofile. I was wondering where I could find information about oprofile source annotation. Thank you. > > Frank, > See http://oprofile.sourceforge.net/doc/opannotate.html. > > -Maynard > > > > > > >> Date: Tue, 26 Apr 2011 14:16:59 -0500 > >> From: may...@us... > >> To: fra...@ho... > >> CC: opr...@li... > >> Subject: Re: oprofile on Centos Linux 5.5 > >> > >> Frank Chang wrote: > >>> > >>> Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, > >>> > >>> opcontrol --shutdown > >>> opcontrol --callgraph=7 > >>> opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe > >>> opcontrol --start > >>> > >>> /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run > >>> > >>> > >>> opcontrol --dump > >>> opreport -c > profile_info.txt > >>> or > >>> opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > >>> > >>> I obtain the following warning: > >>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > >>> Either this is the wrong binary or the binary has been modified since the sample file was created. > >>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe > >>> > >>> I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. > >> > >> Frank, > >> I don't see an 'opcontrol --reset' above in your sequence of commands, so if you've run this sequence more than once, then you'll have sample data from multiple profile runs in oprofile's sample database. And very likely, some of the older sample data was from an older version of libmdMatchup.so. > >> > >> A couple tips: > >> - Use '--separate=lib' option as it helps match up library samples with your executable > >> - Start simple; set --callgraph=0 and --image=none. Once you have the basics running and you understand what you're seeing in the reports that opreport generates, then play with the various options. > >> > >> -Maynard > >>> > >>> > >>> > >>> > >>> ------------------------------------------------------------------------------ > >>> WhatsUp Gold - Download Free Network Management Software > >>> The most intuitive, comprehensive, and cost-effective network > >>> management toolset available today. Delivers lowest initial > >>> acquisition cost and overall TCO of any competing solution. > >>> http://p.sf.net/sfu/whatsupgold-sd > >>> > >>> > >>> > >>> _______________________________________________ > >>> oprofile-list mailing list > >>> opr...@li... > >>> https://lists.sourceforge.net/lists/listinfo/oprofile-list > >> > > > |
From: Frank C. <fra...@ho...> - 2011-04-27 16:46:58
|
Maynard Johnson, I read this link which you forwarded to me, http://oprofile.sourceforge.net/doc/opannotate.html. Then, I started examining my opannotate output. After reading the opannoate article, I could basically understand the opannotate output. For example, 608 0.0011 :NFA::~NFA(){ /* __automata_combined_test3__::NFA::~NFA() total: 2236 0.0041 */ 46 8.4e-05 : delete this->transitions; 33 6.1e-05 : delete this->final_states; 257 4.7e-04 : delete this->_start_state; 73 1.3e-04 : delete this->tmpdictvector; //auto_vector destructor 191 3.5e-04 : delete this->tmpsetvector; //auto_vector destructor 152 2.8e-04 : delete this->tmpcurrvector; //auto_vector destructor 291 5.3e-04 : delete this->tmpnextstatevector; //auto_vector destructor 176 3.2e-04 : delete this->tmpblahvector; //auto_vector destructor 101 1.9e-04 : delete this->tmpexpanddictvector; //auto_vector destructor 250 4.6e-04 : delete this->tmpexpandsetvector; //auto_vector destructor 58 1.1e-04 :} Here we observe that the total count for the NFA destructor is 2236. If we add up the counts next to each annotated source line in the NFA destructor, we see that the total ,2236, agrees with the sum of 608 + 46 + 33 + 257 + 73 + 191 + 152 + 291 + 176 + 101 + 250 + 58. This is because we do not use any inline functions. However, we were wondering why the individual counts on each annotated source line are not evenly distributed. Is it because we are using a 1 millisecond CPU sampling interval? How should we set up OProfile so that the individual line counts are evenly distributed? Here is another example: 1015 0.0019 :DFA::~DFA(){ /* __automata_combined_test3__::DFA::~DFA() total: 4990 0.0092 */ 221 4.1e-04 : delete this->transitions; 139 2.6e-04 : delete this->defaults; 759 0.0014 : delete this->final_states; 75 1.4e-04 : delete this->start_state; 310 5.7e-04 : delete this->tmpdictvector; //auto_vector destructor 308 5.7e-04 : delete this->tmpstatevector; //auto_vector destructor 143 2.6e-04 : delete this->tmpfirstvector; //auto_vector destructor 182 3.3e-04 : delete this->tmpcorrectvector; //auto_vector destructor 164 3.0e-04 : delete this->tmpsubstitutevector; //auto_vector destructor 350 6.4e-04 : delete this->tmpdeletionvector; //auto_vector destructor 165 3.0e-04 : delete this->tmpinsertvector; //auto_vector destructor 101 1.9e-04 : delete this->tmptermblahvector; //auto_vector destructor 392 7.2e-04 : delete this->tmpenumiterpvector; //auto_vector destructor 135 2.5e-04 : delete this->tmpterm1vector; //auto_vector destructor 139 2.6e-04 : delete this->tmpterm2vector; //auto_vector destructor 138 2.5e-04 : delete this->tmpfinalvector; //auto_vector destructor 254 4.7e-04 :} Again, the total for the DFA destructor is 4990 which equals the sum of the individual source line counts, 1015 + 221 + 139 + 759 + 75 + 310 + 308 + 143 + 182 + 164 + 350 + 165 + 101 + 392 + 135 + 139 + 254. However, the individual line counts are not evenly distributed. In the NFA and DFA destructor source code, I have identified the auto_vector destructor calls. Here is the annotated code for the auto_vector destructor: 3698 0.0068 : ~auto_vector() /* auto_vector<_dict<__shedskin__::str*, set<__shedskin__::tuple2<int, int>*>*> >::~auto_vector() 6996 0.0128, auto_vector<_set<__shedskin__::tuple2<int, int>*> >::~auto_vector() 17487 0.0321, auto_vector<__iter<__shedskin__::tuple2<int, __shedskin__::str*>*> >::~auto_vector() 3153 0.0058, auto_vector<__iter<__shedskin__::str*> >::~auto_vector() 2412 0.0044, auto_vector<tuple2<int, int> >::~auto_vector() 20428 0.0375, total: 50476 0.0927 */ : { 46778 0.0859 : delete []_arr; : } Here are the auto_vector destructor total is 50476 which agrees with the partial template counts 6996 + 17487 + 3153 + 2412 + 20428 = 50476. However since the auto_vector destructor is only invoked in the NFA and DFA destructors shown earlier, the auto_vector destructor total , 50476, does not agree with the the total number of invocations of the auto_vector destructor in the NFA destructor and DFA destructor. OProfile tells us the ~DFA destructor is called 4990 times. Each time the DFA destructor is run, there are 12 invocations of the auto_vector destructor. OProfile tells us the ~NFA destructor is called 2236 times. Each time the NFA destructor is run, there are 7 invocations of auto_vector. If we calculate (4990 * 12) + (2236 *7 ) , that equals 59880 + 15652 = 75532. So, we should expect to observe 75532 invocations of the auto_ vector destructor in the OProfile opannoate output. Instead, opannoate tells us the auto_vector destructor was called 50476 times. Please tell us how we configure Oprofile , OpControl , Opreport and/or opannotate so we can sample all the auto_vector destructors. Thank you. > Date: Tue, 26 Apr 2011 18:44:20 -0500 > From: may...@us... > To: fra...@ho... > CC: opr...@li... > Subject: Re: oprofile on Centos Linux 5.5 > > Frank Chang wrote: > > > > Maynard Johnson, Thank you for your reply. Your suggestions were very useful. We were wondering when we run : opcontrol --separate=library . We tried running opcontrol --separate=library before opcontrol --start and after opcontrol --start. In either case, > > we are obtaining the warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > > Either this is the wrong binary or the binary has been modified since the sample file was created. > > So we decided to remove the /var/lib/oprofile/samples subdirectory and use opcontrol --reset. Now , we are no longer obtaining any warning messages. > > My supervisor asked me if oprofile could annotate source code. So I tried the command: opannotate --source --output-dir=/home/frankc/src/annotated ./Mary15.exe. When I looked in /home/frankc/src/annotated/..... I observed that certain cpp and hpp files were annotated with profiling measurements. I am just a newbie to oprofile. I was wondering where I could find information about oprofile source annotation. Thank you. > > Frank, > See http://oprofile.sourceforge.net/doc/opannotate.html. > > -Maynard > > > > > > >> Date: Tue, 26 Apr 2011 14:16:59 -0500 > >> From: may...@us... > >> To: fra...@ho... > >> CC: opr...@li... > >> Subject: Re: oprofile on Centos Linux 5.5 > >> > >> Frank Chang wrote: > >>> > >>> Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, > >>> > >>> opcontrol --shutdown > >>> opcontrol --callgraph=7 > >>> opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe > >>> opcontrol --start > >>> > >>> /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run > >>> > >>> > >>> opcontrol --dump > >>> opreport -c > profile_info.txt > >>> or > >>> opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > >>> > >>> I obtain the following warning: > >>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > >>> Either this is the wrong binary or the binary has been modified since the sample file was created. > >>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe > >>> > >>> I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. > >> > >> Frank, > >> I don't see an 'opcontrol --reset' above in your sequence of commands, so if you've run this sequence more than once, then you'll have sample data from multiple profile runs in oprofile's sample database. And very likely, some of the older sample data was from an older version of libmdMatchup.so. > >> > >> A couple tips: > >> - Use '--separate=lib' option as it helps match up library samples with your executable > >> - Start simple; set --callgraph=0 and --image=none. Once you have the basics running and you understand what you're seeing in the reports that opreport generates, then play with the various options. > >> > >> -Maynard > >>> > >>> > >>> > >>> > >>> ------------------------------------------------------------------------------ > >>> WhatsUp Gold - Download Free Network Management Software > >>> The most intuitive, comprehensive, and cost-effective network > >>> management toolset available today. Delivers lowest initial > >>> acquisition cost and overall TCO of any competing solution. > >>> http://p.sf.net/sfu/whatsupgold-sd > >>> > >>> > >>> > >>> _______________________________________________ > >>> oprofile-list mailing list > >>> opr...@li... > >>> https://lists.sourceforge.net/lists/listinfo/oprofile-list > >> > > > |
From: Maynard J. <may...@us...> - 2011-04-27 22:55:35
|
Frank Chang wrote: > > Maynard Johnson, I read this link which you forwarded to me, http://oprofile.sourceforge.net/doc/opannotate.html. > Then, I started examining my opannotate output. After reading the opannoate article, I could basically understand the opannotate output. For example, > > 608 0.0011 :NFA::~NFA(){ > /* __automata_combined_test3__::NFA::~NFA() total: 2236 0.0041 */ > 46 8.4e-05 : delete this->transitions; > 33 6.1e-05 : delete this->final_states; > 257 4.7e-04 : delete this->_start_state; > 73 1.3e-04 : delete this->tmpdictvector; //auto_vector destructor > 191 3.5e-04 : delete this->tmpsetvector; //auto_vector destructor > 152 2.8e-04 : delete this->tmpcurrvector; //auto_vector destructor > 291 5.3e-04 : delete this->tmpnextstatevector; //auto_vector destructor > 176 3.2e-04 : delete this->tmpblahvector; //auto_vector destructor > 101 1.9e-04 : delete this->tmpexpanddictvector; //auto_vector destructor > 250 4.6e-04 : delete this->tmpexpandsetvector; //auto_vector destructor > 58 1.1e-04 :} > > Here we observe that the total count for the NFA destructor is 2236. If we add up the counts next to each annotated source line in the NFA destructor, we see that the total ,2236, agrees with the sum of 608 + 46 + 33 + 257 + 73 + 191 + 152 + 291 + 176 + 101 + 250 + 58. This is because we do not use any inline functions. > However, we were wondering why the individual counts on each annotated source line are not evenly distributed. Is it because we are using a 1 millisecond CPU sampling interval? How should we set up OProfile so that the individual line counts are evenly distributed? OProfile is a statistical profiler, which means that every x-number of ticks (and ticks can be either clock ticks or hardware events such as cycles, cache misses, etc.), the profiler takes a sample of where the program was at the time of the sample. While this may seem totally random when you take only a few samples, as the number and frequency of samples increase, the accuracy of the profile increases where you see a higher number of samples collecting around the truly "hot" areas of code. So don't expect the number of samples for a given function or piece of code to match the number of times you expect that code to have executed. If it took a short period of time to execute, then odds are there are few (or even no) samples taken during its execution. -Maynard > Here is another example: > > 1015 0.0019 :DFA::~DFA(){ > /* __automata_combined_test3__::DFA::~DFA() total: 4990 0.0092 */ > 221 4.1e-04 : delete this->transitions; > 139 2.6e-04 : delete this->defaults; > 759 0.0014 : delete this->final_states; > 75 1.4e-04 : delete this->start_state; > 310 5.7e-04 : delete this->tmpdictvector; //auto_vector destructor > 308 5.7e-04 : delete this->tmpstatevector; //auto_vector destructor > 143 2.6e-04 : delete this->tmpfirstvector; //auto_vector destructor > 182 3.3e-04 : delete this->tmpcorrectvector; //auto_vector destructor > 164 3.0e-04 : delete this->tmpsubstitutevector; //auto_vector destructor > 350 6.4e-04 : delete this->tmpdeletionvector; //auto_vector destructor > 165 3.0e-04 : delete this->tmpinsertvector; //auto_vector destructor > 101 1.9e-04 : delete this->tmptermblahvector; //auto_vector destructor > 392 7.2e-04 : delete this->tmpenumiterpvector; //auto_vector destructor > 135 2.5e-04 : delete this->tmpterm1vector; //auto_vector destructor > 139 2.6e-04 : delete this->tmpterm2vector; //auto_vector destructor > 138 2.5e-04 : delete this->tmpfinalvector; //auto_vector destructor > 254 4.7e-04 :} > > Again, the total for the DFA destructor is 4990 which equals the sum of the individual source line counts, 1015 + 221 + 139 + 759 + 75 + 310 + 308 + 143 + 182 + 164 + 350 + 165 + 101 + 392 + 135 + 139 + 254. However, the individual line counts are not evenly distributed. > In the NFA and DFA destructor source code, I have identified the auto_vector destructor calls. > Here is the annotated code for the auto_vector destructor: > > 3698 0.0068 : ~auto_vector() > /* auto_vector<_dict<__shedskin__::str*, > set<__shedskin__::tuple2<int, int>*>*> >::~auto_vector() > 6996 0.0128, > auto_vector<_set<__shedskin__::tuple2<int, int>*> >::~auto_vector() > 17487 0.0321, > auto_vector<__iter<__shedskin__::tuple2<int, __shedskin__::str*>*> >::~auto_vector() > 3153 0.0058, > auto_vector<__iter<__shedskin__::str*> >::~auto_vector() > 2412 0.0044, > auto_vector<tuple2<int, int> >::~auto_vector() > 20428 0.0375, > total: 50476 0.0927 */ > : { > 46778 0.0859 : delete []_arr; > : } > > Here are the auto_vector destructor total is 50476 which agrees with the partial template counts 6996 + 17487 + 3153 + 2412 + 20428 = 50476. However since the auto_vector destructor is only invoked in the NFA and DFA destructors shown earlier, the auto_vector destructor total , 50476, does not agree with the the total number of invocations of the auto_vector destructor in the NFA destructor and DFA destructor. > OProfile tells us the ~DFA destructor is called 4990 times. Each time the DFA destructor is run, there are 12 invocations of the auto_vector destructor. OProfile tells us the ~NFA destructor is called 2236 times. Each time the NFA destructor is run, there are 7 invocations of auto_vector. If we calculate (4990 * 12) + (2236 *7 ) , that equals 59880 + 15652 = 75532. So, we should expect to observe 75532 invocations of the auto_ vector destructor in the OProfile opannoate output. Instead, opannoate tells us the auto_vector destructor was called 50476 times. > Please tell us how we configure Oprofile , OpControl , Opreport and/or opannotate so we can sample all the auto_vector destructors. Thank you. > >> Date: Tue, 26 Apr 2011 18:44:20 -0500 >> From: may...@us... >> To: fra...@ho... >> CC: opr...@li... >> Subject: Re: oprofile on Centos Linux 5.5 >> >> Frank Chang wrote: >>> >>> Maynard Johnson, Thank you for your reply. Your suggestions were very useful. We were wondering when we run : opcontrol --separate=library . We tried running opcontrol --separate=library before opcontrol --start and after opcontrol --start. In either case, >>> we are obtaining the warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so >>> Either this is the wrong binary or the binary has been modified since the sample file was created. >>> So we decided to remove the /var/lib/oprofile/samples subdirectory and use opcontrol --reset. Now , we are no longer obtaining any warning messages. >>> My supervisor asked me if oprofile could annotate source code. So I tried the command: opannotate --source --output-dir=/home/frankc/src/annotated ./Mary15.exe. When I looked in /home/frankc/src/annotated/..... I observed that certain cpp and hpp files were annotated with profiling measurements. I am just a newbie to oprofile. I was wondering where I could find information about oprofile source annotation. Thank you. >> >> Frank, >> See http://oprofile.sourceforge.net/doc/opannotate.html. >> >> -Maynard >> >>> >>> >>>> Date: Tue, 26 Apr 2011 14:16:59 -0500 >>>> From: may...@us... >>>> To: fra...@ho... >>>> CC: opr...@li... >>>> Subject: Re: oprofile on Centos Linux 5.5 >>>> >>>> Frank Chang wrote: >>>>> >>>>> Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, >>>>> >>>>> opcontrol --shutdown >>>>> opcontrol --callgraph=7 >>>>> opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe >>>>> opcontrol --start >>>>> >>>>> /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run >>>>> >>>>> >>>>> opcontrol --dump >>>>> opreport -c > profile_info.txt >>>>> or >>>>> opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so >>>>> >>>>> I obtain the following warning: >>>>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so >>>>> Either this is the wrong binary or the binary has been modified since the sample file was created. >>>>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe >>>>> >>>>> I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. >>>> >>>> Frank, >>>> I don't see an 'opcontrol --reset' above in your sequence of commands, so if you've run this sequence more than once, then you'll have sample data from multiple profile runs in oprofile's sample database. And very likely, some of the older sample data was from an older version of libmdMatchup.so. >>>> >>>> A couple tips: >>>> - Use '--separate=lib' option as it helps match up library samples with your executable >>>> - Start simple; set --callgraph=0 and --image=none. Once you have the basics running and you understand what you're seeing in the reports that opreport generates, then play with the various options. >>>> >>>> -Maynard >>>>> >>>>> >>>>> >>>>> >>>>> ------------------------------------------------------------------------------ >>>>> WhatsUp Gold - Download Free Network Management Software >>>>> The most intuitive, comprehensive, and cost-effective network >>>>> management toolset available today. Delivers lowest initial >>>>> acquisition cost and overall TCO of any competing solution. >>>>> http://p.sf.net/sfu/whatsupgold-sd >>>>> >>>>> >>>>> >>>>> _______________________________________________ >>>>> oprofile-list mailing list >>>>> opr...@li... >>>>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >>>> >>> >> > |
From: Frank C. <fra...@ho...> - 2011-04-28 00:23:50
|
Maynard Johnson, Thank you explaining my results to me. I took only a short sample as you deduced. I will have to take bigger samples in the future. Thank you again for all for your help, > Date: Wed, 27 Apr 2011 17:55:44 -0500 > From: may...@us... > To: fra...@ho... > CC: opr...@li... > Subject: Re: opannotate on Centos Linux 5.5 > > Frank Chang wrote: > > > > Maynard Johnson, I read this link which you forwarded to me, http://oprofile.sourceforge.net/doc/opannotate.html. > > Then, I started examining my opannotate output. After reading the opannoate article, I could basically understand the opannotate output. For example, > > > > 608 0.0011 :NFA::~NFA(){ > > /* __automata_combined_test3__::NFA::~NFA() total: 2236 0.0041 */ > > 46 8.4e-05 : delete this->transitions; > > 33 6.1e-05 : delete this->final_states; > > 257 4.7e-04 : delete this->_start_state; > > 73 1.3e-04 : delete this->tmpdictvector; //auto_vector destructor > > 191 3.5e-04 : delete this->tmpsetvector; //auto_vector destructor > > 152 2.8e-04 : delete this->tmpcurrvector; //auto_vector destructor > > 291 5.3e-04 : delete this->tmpnextstatevector; //auto_vector destructor > > 176 3.2e-04 : delete this->tmpblahvector; //auto_vector destructor > > 101 1.9e-04 : delete this->tmpexpanddictvector; //auto_vector destructor > > 250 4.6e-04 : delete this->tmpexpandsetvector; //auto_vector destructor > > 58 1.1e-04 :} > > > > Here we observe that the total count for the NFA destructor is 2236. If we add up the counts next to each annotated source line in the NFA destructor, we see that the total ,2236, agrees with the sum of 608 + 46 + 33 + 257 + 73 + 191 + 152 + 291 + 176 + 101 + 250 + 58. This is because we do not use any inline functions. > > However, we were wondering why the individual counts on each annotated source line are not evenly distributed. Is it because we are using a 1 millisecond CPU sampling interval? How should we set up OProfile so that the individual line counts are evenly distributed? > > OProfile is a statistical profiler, which means that every x-number of ticks (and ticks can be either clock ticks or hardware events such as cycles, cache misses, etc.), the profiler takes a sample of where the program was at the time of the sample. While this may seem totally random when you take only a few samples, as the number and frequency of samples increase, the accuracy of the profile increases where you see a higher number of samples collecting around the truly "hot" areas of code. So don't expect the number of samples for a given function or piece of code to match the number of times you expect that code to have executed. If it took a short period of time to execute, then odds are there are few (or even no) samples taken during its execution. > > -Maynard > > Here is another example: > > > > 1015 0.0019 :DFA::~DFA(){ > > /* __automata_combined_test3__::DFA::~DFA() total: 4990 0.0092 */ > > 221 4.1e-04 : delete this->transitions; > > 139 2.6e-04 : delete this->defaults; > > 759 0.0014 : delete this->final_states; > > 75 1.4e-04 : delete this->start_state; > > 310 5.7e-04 : delete this->tmpdictvector; //auto_vector destructor > > 308 5.7e-04 : delete this->tmpstatevector; //auto_vector destructor > > 143 2.6e-04 : delete this->tmpfirstvector; //auto_vector destructor > > 182 3.3e-04 : delete this->tmpcorrectvector; //auto_vector destructor > > 164 3.0e-04 : delete this->tmpsubstitutevector; //auto_vector destructor > > 350 6.4e-04 : delete this->tmpdeletionvector; //auto_vector destructor > > 165 3.0e-04 : delete this->tmpinsertvector; //auto_vector destructor > > 101 1.9e-04 : delete this->tmptermblahvector; //auto_vector destructor > > 392 7.2e-04 : delete this->tmpenumiterpvector; //auto_vector destructor > > 135 2.5e-04 : delete this->tmpterm1vector; //auto_vector destructor > > 139 2.6e-04 : delete this->tmpterm2vector; //auto_vector destructor > > 138 2.5e-04 : delete this->tmpfinalvector; //auto_vector destructor > > 254 4.7e-04 :} > > > > Again, the total for the DFA destructor is 4990 which equals the sum of the individual source line counts, 1015 + 221 + 139 + 759 + 75 + 310 + 308 + 143 + 182 + 164 + 350 + 165 + 101 + 392 + 135 + 139 + 254. However, the individual line counts are not evenly distributed. > > In the NFA and DFA destructor source code, I have identified the auto_vector destructor calls. > > Here is the annotated code for the auto_vector destructor: > > > > 3698 0.0068 : ~auto_vector() > > /* auto_vector<_dict<__shedskin__::str*, > > set<__shedskin__::tuple2<int, int>*>*> >::~auto_vector() > > 6996 0.0128, > > auto_vector<_set<__shedskin__::tuple2<int, int>*> >::~auto_vector() > > 17487 0.0321, > > auto_vector<__iter<__shedskin__::tuple2<int, __shedskin__::str*>*> >::~auto_vector() > > 3153 0.0058, > > auto_vector<__iter<__shedskin__::str*> >::~auto_vector() > > 2412 0.0044, > > auto_vector<tuple2<int, int> >::~auto_vector() > > 20428 0.0375, > > total: 50476 0.0927 */ > > : { > > 46778 0.0859 : delete []_arr; > > : } > > > > Here are the auto_vector destructor total is 50476 which agrees with the partial template counts 6996 + 17487 + 3153 + 2412 + 20428 = 50476. However since the auto_vector destructor is only invoked in the NFA and DFA destructors shown earlier, the auto_vector destructor total , 50476, does not agree with the the total number of invocations of the auto_vector destructor in the NFA destructor and DFA destructor. > > OProfile tells us the ~DFA destructor is called 4990 times. Each time the DFA destructor is run, there are 12 invocations of the auto_vector destructor. OProfile tells us the ~NFA destructor is called 2236 times. Each time the NFA destructor is run, there are 7 invocations of auto_vector. If we calculate (4990 * 12) + (2236 *7 ) , that equals 59880 + 15652 = 75532. So, we should expect to observe 75532 invocations of the auto_ vector destructor in the OProfile opannoate output. Instead, opannoate tells us the auto_vector destructor was called 50476 times. > > Please tell us how we configure Oprofile , OpControl , Opreport and/or opannotate so we can sample all the auto_vector destructors. Thank you. > > > >> Date: Tue, 26 Apr 2011 18:44:20 -0500 > >> From: may...@us... > >> To: fra...@ho... > >> CC: opr...@li... > >> Subject: Re: oprofile on Centos Linux 5.5 > >> > >> Frank Chang wrote: > >>> > >>> Maynard Johnson, Thank you for your reply. Your suggestions were very useful. We were wondering when we run : opcontrol --separate=library . We tried running opcontrol --separate=library before opcontrol --start and after opcontrol --start. In either case, > >>> we are obtaining the warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > >>> Either this is the wrong binary or the binary has been modified since the sample file was created. > >>> So we decided to remove the /var/lib/oprofile/samples subdirectory and use opcontrol --reset. Now , we are no longer obtaining any warning messages. > >>> My supervisor asked me if oprofile could annotate source code. So I tried the command: opannotate --source --output-dir=/home/frankc/src/annotated ./Mary15.exe. When I looked in /home/frankc/src/annotated/..... I observed that certain cpp and hpp files were annotated with profiling measurements. I am just a newbie to oprofile. I was wondering where I could find information about oprofile source annotation. Thank you. > >> > >> Frank, > >> See http://oprofile.sourceforge.net/doc/opannotate.html. > >> > >> -Maynard > >> > >>> > >>> > >>>> Date: Tue, 26 Apr 2011 14:16:59 -0500 > >>>> From: may...@us... > >>>> To: fra...@ho... > >>>> CC: opr...@li... > >>>> Subject: Re: oprofile on Centos Linux 5.5 > >>>> > >>>> Frank Chang wrote: > >>>>> > >>>>> Hi, I installed oprofile 0.9.4 on Centos Linux 5.5 this past Saturday. Since then I have been trying to learn how to use oprofile 0.9.4 on Centos Linux 5.5. If I follow the following steps running as root, > >>>>> > >>>>> opcontrol --shutdown > >>>>> opcontrol --callgraph=7 > >>>>> opcontrol --image=/home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe > >>>>> opcontrol --start > >>>>> > >>>>> /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/Mary48.exe --run > >>>>> > >>>>> > >>>>> opcontrol --dump > >>>>> opreport -c > profile_info.txt > >>>>> or > >>>>> opreport -l /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > >>>>> > >>>>> I obtain the following warning: > >>>>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpLib/lirh5g_deb/libmdMatchup.so > >>>>> Either this is the wrong binary or the binary has been modified since the sample file was created. > >>>>> warning: the last modified time of the binary file does not match that of the sample file for /home/frankc/DQTTest5/MatchUpTest/lirh5g_deb/MatchUpAccurate.exe > >>>>> > >>>>> I am wondering how to prevent this warning message from occuring because it indicates our profiling results may be incorrect. Thank you. > >>>> > >>>> Frank, > >>>> I don't see an 'opcontrol --reset' above in your sequence of commands, so if you've run this sequence more than once, then you'll have sample data from multiple profile runs in oprofile's sample database. And very likely, some of the older sample data was from an older version of libmdMatchup.so. > >>>> > >>>> A couple tips: > >>>> - Use '--separate=lib' option as it helps match up library samples with your executable > >>>> - Start simple; set --callgraph=0 and --image=none. Once you have the basics running and you understand what you're seeing in the reports that opreport generates, then play with the various options. > >>>> > >>>> -Maynard > >>>>> > >>>>> > >>>>> > >>>>> > >>>>> ------------------------------------------------------------------------------ > >>>>> WhatsUp Gold - Download Free Network Management Software > >>>>> The most intuitive, comprehensive, and cost-effective network > >>>>> management toolset available today. Delivers lowest initial > >>>>> acquisition cost and overall TCO of any competing solution. > >>>>> http://p.sf.net/sfu/whatsupgold-sd > >>>>> > >>>>> > >>>>> > >>>>> _______________________________________________ > >>>>> oprofile-list mailing list > >>>>> opr...@li... > >>>>> https://lists.sourceforge.net/lists/listinfo/oprofile-list > >>>> > >>> > >> > > > |