profiler.ccDescription: Text Data
|
| From: | Muthiah Annamalai |
| Subject: | Re: Octave profiler, |
| Date: | Sun, 28 Jan 2007 20:55:35 -0600 |
On Sat, 2007-01-27 at 07:20 -0600, Muthiah Annamalai wrote:
> On Thu, 2007-01-25 at 20:28 -0600, Muthiah Annamalai wrote:
> > <SNIP>
> > In typical implementations,this function delegates events to particular
> > handlers.
> >
> > Essentially, we need to be able to provide a hookup like
> > 'sys.setprofile' in Octave core, we may be able to profile calls to
> > C/C++ , Fortran and Octave routines
>
> I was wondering if the proper positions to insert hooks for invoking the
> profiler would be at the point in subsref() member functions, before the
> point where the code calls on do_multi_index_op() in the following
> source files:
>
> Source File Profiler Events
> ---+-----------------------------+---------------------------------------
> 1 ov-mex-fcn.cc mex-call, mex-ret, mex-exception
> 2 ov-user-fcn.cc o-call, o-ret, o-exception
> 3 ov-mapper.cc mapper-call,mapper-ret,exception
> 4 ov-builtin.cc builtin-call,ret,exception
>
> Will this be the proper places to add profiling code? I also want to
> know if we will not have really bad overheads due to this. AFAIK other
> languages (Ruby, Python) report about 30% overhead when using a
> compiled-with-core profiler, that does a full call-graph profiling.
>
> For Matlab compatibility, Octave needs such a call-graph based
> profiling. Even if Octave uses just flat-profiling with just reporting
> of number of calls, times for calls, Octave needs to provide the
> profiler hook like I mentioned is done in Python (and in Ruby, with
> set_profile_func ).
>
> So, we need a hook function. But is this the right place to provide
> them?
>
> ~ Muthiah
I have implemented a rudimentary "flat-profiler" that can just give
statistics of the cpu-time of the functions (only), self & total average
runtimes, and frequency of call to each function.
This code is a C++ rewrite of the Ruby's flat-profiler from
$(Ruby-Install-Path)/lib/profiler.rb authored by 'Matz' (Yukihiro
Matsumoto).
Sample output of profile command testcase 'testprofile.m' (attached)
looks like:
% cumulative self self total
time seconds seconds calls ms/call ms/call name
2.41 0.00 0.00 4 0.06 0.06 anonymous1
2.57 0.00 0.00 4 0.06 0.06 anonymous2
0.00 0.00 0.00 1 0.00 9.71 #toplevel
ans = info
I have also added some elementary support for 'event-based' profiler ,
from the Octave side, that notifies the routines for 'calls', and
'returns' from functions. Exception handling is not implemented.
The API support touches the 4 files mentioned in the previous post.
>From this point, a simple call-graph profiler can also be implemented
with the present infrastructure. The python profiler ('import profiler')
does something like this, and serves as a good template.
[Profiler API Support]
Many design decisions remain to be made, which I must leave it to better
experienced. I would personally prefer a 'event-based' profiler API like
the JAVA's JVMPI (JVM Profiler Interface) which lets people build/use a
sophisticated or simple profiler based on the application.
Please see JVM-PI design at
http://java.sun.com/j2se/1.4.2/docs/guide/jvmpi/jvmpi.html.
There are following good points about the code,
1. It recognizes anonymous functions
2. Does CPU times with least overhead.
3. Can write a basic call-graph profiler
4. Works in rudimentary Matlab syntax
Caveats of the present code,
0. Cannot lookinto execution times of specific lines-of-code
1. Not Matlab compatible
2. Cannot handle exceptions in profiler gracefully.
3. Regular caveats of a flat-profiler in not knowing context
of the function calls; (call-graph based profilers help here,
sort-of)
4. No event filtering
5. Sub-Optimal API design
For compatibility with Matlab, it suffices to provide an API to reach
the level of a event-based, call-graph profiler with access to
individual lines.
I am posting the diffs against the files, and the 2 new files for
octave/src/profile.cc & octave/src/profile.h
Please comment.
Thanks,
-Muthiah
// context diffs
Index: Makefile.in
===================================================================
RCS file: /cvs/octave/src/Makefile.in,v
retrieving revision 1.425
diff -c -r1.425 Makefile.in
*** Makefile.in 5 Jan 2007 22:54:10 -0000 1.425
--- Makefile.in 29 Jan 2007 02:39:26 -0000
***************
*** 109,115 ****
parse.h pr-output.h procstream.h sighandlers.h siglist.h \
sparse-xdiv.h sparse-xpow.h symtab.h sysdep.h \
token.h toplev.h unwind-prot.h utils.h variables.h version.h \
! xdiv.h xpow.h \
$(OV_INCLUDES) \
$(PT_INCLUDES) \
$(OV_SPARSE_INCLUDES)
--- 109,115 ----
parse.h pr-output.h procstream.h sighandlers.h siglist.h \
sparse-xdiv.h sparse-xpow.h symtab.h sysdep.h \
token.h toplev.h unwind-prot.h utils.h variables.h version.h \
! xdiv.h xpow.h profiler.h\
$(OV_INCLUDES) \
$(PT_INCLUDES) \
$(OV_SPARSE_INCLUDES)
***************
*** 179,185 ****
parse.y pr-output.cc procstream.cc sighandlers.cc \
siglist.c sparse-xdiv.cc sparse-xpow.cc strfns.cc \
symtab.cc syscalls.cc sysdep.cc token.cc toplev.cc \
! unwind-prot.cc utils.cc variables.cc xdiv.cc xpow.cc \
$(OV_SRC) \
$(PT_SRC)
--- 179,185 ----
parse.y pr-output.cc procstream.cc sighandlers.cc \
siglist.c sparse-xdiv.cc sparse-xpow.cc strfns.cc \
symtab.cc syscalls.cc sysdep.cc token.cc toplev.cc \
! unwind-prot.cc utils.cc variables.cc xdiv.cc xpow.cc profiler.cc\
$(OV_SRC) \
$(PT_SRC)
Index: debug.cc
===================================================================
RCS file: /cvs/octave/src/debug.cc,v
retrieving revision 1.20
diff -c -r1.20 debug.cc
*** debug.cc 6 Apr 2006 19:38:34 -0000 1.20
--- debug.cc 29 Jan 2007 02:39:26 -0000
***************
*** 348,355 ****
os << "dbtype: unable to open `" << ff << "' for reading!\n";
}
else
! os << "dbtype: unkown function";
}
DEFCMD (dbtype, args, ,
--- 348,361 ----
os << "dbtype: unable to open `" << ff << "' for reading!\n";
}
else
! os << "dbtype: unkown function "<< name << "\n";
+ os.flush();
+ }
+
+ inline int min(int x,int y)
+ {
+ return (x< y)?x: y;
}
DEFCMD (dbtype, args, ,
***************
*** 401,425 ****
int start = atoi (start_str.c_str ());
int end = atoi (end_str.c_str ());
! if (start < end)
do_dbtype (octave_stdout,
dbg_fcn->name (), start, end);
else
error ("dbtype: the start line must be less than the
end line\n");
}
else
! error ("dbtype: if you specify lines it must be like
`start:end`");
}
}
break;
! case 2: // (dbtype func start:end)
dbg_fcn = get_user_function (argv[1]);
if (dbg_fcn)
{
std::string arg = argv[2];
!
size_t ind = arg.find (':');
if (ind != NPOS)
--- 407,437 ----
int start = atoi (start_str.c_str ());
int end = atoi (end_str.c_str ());
! if (min(start,end) <= 0)
! error("dbtype: the start & end lines must be >= 1\n");
!
! if (start <= end)
do_dbtype (octave_stdout,
dbg_fcn->name (), start, end);
else
error ("dbtype: the start line must be less than the
end line\n");
}
else
! {
! error ("dbtype: if you specify lines it must be like
`start:end`");
! }
}
}
break;
! case 2: // (dbtype func start:end) , (dbtype func start)
dbg_fcn = get_user_function (argv[1]);
if (dbg_fcn)
{
std::string arg = argv[2];
! int start=0;
! int end=0;
size_t ind = arg.find (':');
if (ind != NPOS)
***************
*** 427,443 ****
std::string start_str = arg.substr (0, ind);
std::string end_str = arg.substr (ind + 1);
! int start = atoi (start_str.c_str ());
! int end = atoi (end_str.c_str ());
!
! if (start < end)
! do_dbtype (octave_stdout,
! dbg_fcn->name (), start, end);
! else
! error ("dbtype: the start line must be less than the end
line
\n");
}
else
! error ("dbtype: if you specify lines it must be like
`start:end`");
}
break;
--- 439,463 ----
std::string start_str = arg.substr (0, ind);
std::string end_str = arg.substr (ind + 1);
! start = atoi (start_str.c_str ());
! end = atoi (end_str.c_str ());
!
! }
! else
! {
! const std::string start_str = arg;
! start = atoi (start_str.c_str ());
! end = start;
}
+
+ if (min(start,end) <= 0)
+ error("dbtype: the start & end lines must be >= 1\n");
+
+ if (start <= end)
+ do_dbtype (octave_stdout,
+ dbg_fcn->name (), start, end);
else
! error ("dbtype: the start line must be less than the end
line\n");
}
break;
Index: ov-builtin.cc
===================================================================
RCS file: /cvs/octave/src/ov-builtin.cc,v
retrieving revision 1.23
diff -c -r1.23 ov-builtin.cc
*** ov-builtin.cc 22 Jun 2006 00:57:28 -0000 1.23
--- ov-builtin.cc 29 Jan 2007 02:39:26 -0000
***************
*** 31,36 ****
--- 31,39 ----
#include "ov.h"
#include "toplev.h"
#include "unwind-prot.h"
+ #include "pager.h"
+
+ #include "profiler.h"
DEFINE_OCTAVE_ALLOCATOR (octave_builtin);
***************
*** 50,57 ****
case '(':
{
int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 : nargout;
!
! retval = do_multi_index_op (tmp_nargout, idx.front ());
}
break;
--- 53,82 ----
case '(':
{
int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 : nargout;
! profiler_call_state cstate=ENDOF_FUNCTION_STATES;
!
! //profiler event "builtin-call"
! //octave_stdout << "ov-builtin: profiler event builtin-call to **>"
<< this->name() << "<** \n";
! cstate=ENTER_FUNCTION;
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,BUILTIN_FUNCTION,cstate);
!
! retval = do_multi_index_op (tmp_nargout, idx.front ());
!
! //profiler event "builtin-exception"
! if (error_state)
! {
! //octave_stdout << "ov-builtin: profiler event
builtin-exception \n";
! cstate=EXCEPTION_IN_FUNCTION;
! }
! //profiler event "builtin-return"
! else
! {
! //octave_stdout << "ov-builtin: profiler event builtin-return
\n";
! cstate=LEAVE_FUNCTION;
! }
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,BUILTIN_FUNCTION,cstate);
}
break;
Index: ov-mapper.cc
===================================================================
RCS file: /cvs/octave/src/ov-mapper.cc,v
retrieving revision 1.32
diff -c -r1.32 ov-mapper.cc
*** ov-mapper.cc 24 Apr 2006 19:13:10 -0000 1.32
--- ov-mapper.cc 29 Jan 2007 02:39:26 -0000
***************
*** 34,39 ****
--- 34,42 ----
#include "ov.h"
#include "toplev.h"
#include "unwind-prot.h"
+ #include "pager.h"
+
+ #include "profiler.h"
DEFINE_OCTAVE_ALLOCATOR (octave_mapper);
***************
*** 397,405 ****
{
case '(':
{
! int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 : nargout;
! retval = do_multi_index_op (tmp_nargout, idx.front ());
}
break;
--- 400,430 ----
{
case '(':
{
! int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 :
nargout;
! profiler_call_state cstate=ENDOF_FUNCTION_STATES;
!
! // enter profiler for mapper-function "mapper-call"
! //octave_stdout << "ov-mapper: profiler event mapper-call to **>" <<
this->name() << "<** \n";
! cstate=ENTER_FUNCTION;
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,BUILTIN_FUNCTION,cstate);
!
! retval = do_multi_index_op (tmp_nargout, idx.front ());
! // leave profiler for mapper-function "mapper-exception"
! if(error_state)
! {
! //octave_stdout << "ov-mapper: profiler event mapper-exception
\n";
! cstate=EXCEPTION_IN_FUNCTION;
! }
! // leave profiler for mapper-function "mapper-return"
! else
! {
! //octave_stdout << "ov-mapper: profiler event mapper-return
\n";
! cstate=LEAVE_FUNCTION;
! }
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,BUILTIN_FUNCTION,cstate);
}
break;
Index: ov-mex-fcn.cc
===================================================================
RCS file: /cvs/octave/src/ov-mex-fcn.cc,v
retrieving revision 1.2
diff -c -r1.2 ov-mex-fcn.cc
*** ov-mex-fcn.cc 20 Oct 2006 16:54:30 -0000 1.2
--- ov-mex-fcn.cc 29 Jan 2007 02:39:26 -0000
***************
*** 35,40 ****
--- 35,43 ----
#include "ov.h"
#include "toplev.h"
#include "unwind-prot.h"
+ #include "pager.h"
+
+ #include "profiler.h"
DEFINE_OCTAVE_ALLOCATOR (octave_mex_function);
***************
*** 87,95 ****
{
case '(':
{
! int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 : nargout;
!
! retval = do_multi_index_op (tmp_nargout, idx.front ());
}
break;
--- 90,120 ----
{
case '(':
{
! int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 :
nargout;
! profiler_call_state cstate=ENDOF_FUNCTION_STATES;
!
! //profiler event "mex-call"
! //octave_stdout << "ov-mex: profiler event mex-call to **>" <<
this->name() << "<** \n";
! cstate=ENTER_FUNCTION;
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,MEX_FUNCTION,cstate);
!
! retval = do_multi_index_op (tmp_nargout, idx.front ());
!
! //profiler event "mex-exception"
! if (error_state)
! {
! //octave_stdout << "ov-mex: profiler event mex-exception \n";
! cstate=EXCEPTION_IN_FUNCTION;
! }
! //profiler event "mex-return"
! else
! {
! //octave_stdout << "ov-mex: profiler event mex-return \n";
! cstate=LEAVE_FUNCTION;
! }
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,BUILTIN_FUNCTION,cstate);
}
break;
Index: ov-usr-fcn.cc
===================================================================
RCS file: /cvs/octave/src/ov-usr-fcn.cc,v
retrieving revision 1.72
diff -c -r1.72 ov-usr-fcn.cc
*** ov-usr-fcn.cc 9 Nov 2006 18:26:56 -0000 1.72
--- ov-usr-fcn.cc 29 Jan 2007 02:39:26 -0000
***************
*** 48,53 ****
--- 48,55 ----
#include "parse.h"
#include "variables.h"
+ #include "profiler.h"
+
// Maximum nesting level for functions called recursively.
static int Vmax_recursion_depth = 256;
***************
*** 204,209 ****
--- 206,212 ----
sr->unprotect ();
}
+ // origin of call -> ()
octave_value_list
octave_user_function::subsref (const std::string& type,
const std::list<octave_value_list>& idx,
***************
*** 215,223 ****
{
case '(':
{
! int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 : nargout;
!
! retval = do_multi_index_op (tmp_nargout, idx.front ());
}
break;
--- 218,271 ----
{
case '(':
{
! int tmp_nargout = (type.length () > 1 && nargout == 0) ? 1 :
nargout;
! profiler_function_type ftype=ENDOF_FUNCTION_TYPES;
! profiler_call_state cstate=ENDOF_FUNCTION_STATES;
!
! // check if we have any useful variant of the function that calls
the
!
! // profiler passes octave-call event. (1 point for anonymous
functions, scripts)
! // profiler::report() should take only the octave_function handle
& determine
! // if these are nested or inline or whatever such.
! //octave_stdout << "ov-user-fcn: do_multi_index_op event:
octave-call to **>";
! if ( is_inline_function() )
! {
! ftype=ANONYMOUS_FUNCTION;
! //octave_stdout << this->name() << "<** (ANONYMOUS/INLINE
FUNCTION)\n";
! }
! else if( is_nested_function() )
! {
! ftype=NESTED_FUNCTION;
! //octave_stdout << this->name() << "<** (NESTED FUNCTION)
\n";
! }
! else
! {
! ftype=OCTAVE_FUNCTION; //standard M-function
! //octave_stdout << this->name() << "<** \n";
! }
!
! cstate=ENTER_FUNCTION;
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,ftype,cstate);
!
! retval = do_multi_index_op (tmp_nargout, idx.front ());
!
! // profiler passes octave-exception event.
! if(error_state)
! {
! //octave_stdout << "ov-user-fcn: do_multi_index_op event:
octave-exception \n";
! cstate=EXCEPTION_IN_FUNCTION;
! }
! // profiler passes octave-return event.
! else
! {
! //octave_stdout << "ov-user-fcn: do_multi_index_op event:
octave-return \n";
! cstate=LEAVE_FUNCTION;
! }
!
! // report the event
! if(octave_profiler::isprofiling())
! octave_profiler::send_event(this,ftype,cstate);
}
break;
***************
*** 243,248 ****
--- 291,297 ----
return retval;
}
+ // add profiling hooks here.
octave_value_list
octave_user_function::do_multi_index_op (int nargout,
const octave_value_list& args)
***************
*** 354,361 ****
// Evaluate the commands that make up the function.
unwind_protect_bool (evaluating_function_body);
! evaluating_function_body = true;
!
cmd_list->eval ();
if (echo_commands)
--- 403,410 ----
// Evaluate the commands that make up the function.
unwind_protect_bool (evaluating_function_body);
! evaluating_function_body = true;
!
cmd_list->eval ();
if (echo_commands)
***************
*** 372,377 ****
--- 421,427 ----
traceback_error ();
goto abort;
}
+
// Copy return values out.
Index: pt-stmt.cc
===================================================================
RCS file: /cvs/octave/src/pt-stmt.cc,v
retrieving revision 1.31
diff -c -r1.31 pt-stmt.cc
*** pt-stmt.cc 24 Jan 2007 20:43:37 -0000 1.31
--- pt-stmt.cc 29 Jan 2007 02:39:26 -0000
***************
*** 84,89 ****
--- 84,90 ----
}
}
+ // point of dispatch the real function
octave_value_list
tree_statement::eval (bool silent, int nargout, bool in_function_body)
{
***************
*** 94,105 ****
if (cmd || expr)
{
unwind_protect_ptr (curr_statement);
! curr_statement = this;
!
maybe_echo_code (in_function_body);
if (cmd)
! cmd->eval ();
else
{
expr->set_print_flag (pf);
--- 95,112 ----
if (cmd || expr)
{
unwind_protect_ptr (curr_statement);
! curr_statement = this;
maybe_echo_code (in_function_body);
if (cmd)
! {
! //octave_function *curr=octave_call_stack::current();
! //octave_stdout << "tree_statement::eval Calling the function ";
! //if(curr)
! //octave_stdout << curr->name();
! //octave_stdout << "\n";
! cmd->eval ();
! }
else
{
expr->set_print_flag (pf);
***************
*** 165,170 ****
--- 172,178 ----
tw.visit_statement (*this);
}
+ // is this the point of dispatch to all functions?
octave_value_list
tree_statement_list::eval (bool silent, int nargout)
{
***************
*** 197,203 ****
break;
if (tree_return_command::returning)
! break;
if (p == end ())
break;
--- 205,214 ----
break;
if (tree_return_command::returning)
! {
! //octave_stdout << "pt-stmt:treelist:eval return \n";
! break;
! }
if (p == end ())
break;
//profile.cc
/*
Copyright (C) 1996, 1997 John W. Eaton
Copyright (C) 2007, Muthiah Annamalai
This file is part of Octave.
Octave is free software; you can redistribute it and/or modify it
under the terms of the GNU General Public License as published by the
Free Software Foundation; either version 2, or (at your option) any
later version.
Octave is distributed in the hope that it will be useful, but WITHOUT
ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
for more details.
You should have received a copy of the GNU General Public License
along with Octave; see the file COPYING. If not, write to the Free
Software Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
02110-1301, USA.
*/
#ifdef HAVE_CONFIG_H
#include <config.h>
#endif
#include "str-vec.h"
#include <defaults.h>
#include "Cell.h"
#include "defun.h"
#include "error.h"
#include "input.h"
#include "oct-obj.h"
#include "ov-usr-fcn.h"
#include "ov.h"
#include "pager.h"
#include "pt-jump.h"
#include "pt-misc.h"
#include "pt-pr-code.h"
#include "pt-stmt.h"
#include "pt-walk.h"
#include "symtab.h"
#include "toplev.h"
#include "unwind-prot.h"
#include "utils.h"
#include "parse.h"
#include "variables.h"
#include "profiler.h"
#include <stack>
#include <map>
#include "systime.h"
#include "pr-output.h"
#include <cstdio>
#include <sstream>
profiler_function
octave_profiler::profile_fcn=static_cast<profiler_function>(NULL);
bool octave_profiler::profiling=false;
void
octave_profiler::send_event(const octave_function
*fcn,profiler_function_type ftype, profiler_call_state cstate)
{
if(!octave_profiler::profiling || !octave_profiler::profile_fcn)
return;
return profile_fcn(fcn,ftype,cstate);
}
bool
octave_profiler::set_profiler(profiler_function profile)
{
octave_profiler::profiling=false;
octave_stdout << "Setting profiler"<<std::endl;
if(profile)
{
octave_stdout << "-> Setting profiler Complete"<<std::endl;
octave_profiler::profile_fcn=profile;
}
else
{
octave_stdout << "-> Setting profiler as empty profiling
function"<<std::endl;
octave_profiler::profile_fcn=static_cast<profiler_function>(NULL);
}
octave_profiler::profiling=true;
return octave_profiler::profiling;
}
bool
octave_profiler::clear_profiler()
{
octave_profiler::profiling=false;
octave_profiler::profile_fcn=static_cast<profiler_function>(NULL);
return true;
}
/*
* Simple flat-profile profiling,
* well all logic/algorithm is shamelessly copied
* from Ruby's ruby/lib/profile.rb
*/
// time data element, goes on stack (used pair<>?)
class time_elem
{
public:
// incremental time from the previous routine
// that a function is called
double delta;
// time for running our kids/child functions
double tick;
//ctors
time_elem(double d,double t): delta(d),tick(t)
{ }
time_elem(): delta(0.0),tick(0.0)
{ }
};
// call-stats-element goes into the hash-map
class call_elem
{
public:
long int ncalls;
double total_time;
double self_time;
std::string key;
bool operator < ( const call_elem* s) const {
return (this->total_time < s->total_time);
}
//ctors
call_elem(long int nc,double tt, double st, std::string k): \
ncalls(nc), total_time(tt), self_time(st), key(k) {}
call_elem(): ncalls(0),total_time(0.00), \
self_time(0.00),key("") {}
};
//time in seconds from epoch() of 1971 Jan 1st something.
inline double now()
{
struct timeval
tv={static_cast<time_t>(0),static_cast<suseconds_t>(0)};
gettimeofday(&tv,NULL);
return static_cast<double>(tv.tv_sec) +
static_cast<double>(tv.tv_usec/1e6);
}
//time in seconds from last start_time,
inline double now(double start_time)
{
struct timeval
tv={static_cast<time_t>(0),static_cast<suseconds_t>(0)};
gettimeofday(&tv,NULL);
return static_cast<double>(tv.tv_sec-start_time) +
static_cast<double>(tv.tv_usec/1.e6);
}
// Implements the real profiler, with
// proper state management & event-handling and
// logging. This
//
class profile_flat: public profile_base
{
//instance variables
public:
static profile_flat *curr_profile;
std::stack<time_elem *> calltimes;
std::map<std::string,call_elem *> callstats;
double time_start;
bool has_profiled;
int anon_count;
profile_flat()
{
time_start=now();
has_profiled=false;
anon_count=0;
}
~profile_flat()
{
curr_profile=static_cast<profile_flat*>(NULL);
}
static bool instance_ok()
{
if(!curr_profile)
{
curr_profile=new profile_flat();
if(!curr_profile)
{
warning("In %s @ %d : Profile_Flat cannot create profiler
\n",__FILE__,__LINE__);
return false;
}
}
return true;
}
//factory method for singleton.
static profile_flat* get_profile(void)
{
if(instance_ok())
return curr_profile;
return NULL;
}
//factory cleanup?
static void clear_profile(void)
{
profile_flat *cprofile = profile_flat::get_profile();
if(cprofile)
{
//cleanup the map and its value part.
std::map<std::string,call_elem *>::iterator
itr=cprofile->callstats.begin();
while(itr!=cprofile->callstats.end())
{
call_elem *ptr=itr->second;
delete ptr;
itr++;
}
delete cprofile;
}
return;
}
static bool has_started()
{
return instance_ok()? curr_profile->has_profiled : false;
}
static void profile_flat::print_stats()
{
if (instance_ok()) curr_profile->print_profile();
else
warning("In %s @ %d : Cannot call print_profile from print_stats
\n",__FILE__,__LINE__);
return;
}
static void profile_func(const octave_function
*fcn,profiler_function_type ftype, profiler_call_state cstate)
{
profile_flat* cprofile=profile_flat::get_profile();
//octave_stdout << "In Profile Func, invoked " << std::endl;
if(cprofile)
cprofile->profile_dispatch_func(fcn,ftype, cstate);
return;
}
static void reset_time_and_counts()
{
if(instance_ok())
{
profile_flat::curr_profile->time_start=now();
profile_flat::curr_profile->anon_count=0;
profile_flat::curr_profile->has_profiled=false;
}
}
static void start_profiling()
{
octave_profiler::set_profiler(&profile_flat::profile_func);
//sync time.
profile_flat::reset_time_and_counts();
return;
}
static void stop_profiling()
{
octave_profiler::clear_profiler();
}
// call processing
void do_profile_call(const octave_function *fcn)
{
//octave_stdout << "**-> Profile Func, (CALL " << fcn->name() << ")
" << std::endl;
this->calltimes.push( new time_elem(now(time_start),0.0) );
return;
}
void do_profile_script_call(const octave_function *fcn,
profiler_function_type ftype)
{
do_profile_call(fcn);
}
void do_profile_compiled_call(const octave_function *fcn,
profiler_function_type ftype)
{
do_profile_call(fcn);
}
// return processing
void do_profile_return(const octave_function
*fcn,profiler_function_type ftype)
{
std::string key;
if(ftype == ANONYMOUS_FUNCTION)
{
//**UGLY-HACK**, can patch ov-fcn-inline.cc/h to work-around this.
//by setting some type of name or hash or ID for the anonymous
functions.
//till then, lets tag this guy using the doc_string.
//***********
octave_function *anonfcn=const_cast<octave_function *>(fcn);
octave_stdout << "ANONFCN " << anonfcn->doc_string() << "\n";
// we're good & living
key=anonfcn->doc_string();
// unless we are unborn
if( key.length() == 0 )
{
std::ostringstream ss;
ss<<"anonymous" << (++anon_count);
key=ss.str();
anonfcn->document(key);
}
}
else
key=fcn->name();
if(!calltimes.empty())
{
time_elem *tick=calltimes.top();
call_elem *ptr=callstats[key];
double cost=now(time_start) - tick->delta;
//throw it out
calltimes.pop();
// create a new element
if(!ptr)
ptr=new call_elem(0,0.0,0.0,key);
// update the usage of the callee-function
ptr->ncalls++;
ptr->total_time += cost;
ptr->self_time += cost - tick->tick;
//stick it back into the hash-table
callstats[key]=ptr;
// free the time_elem
delete tick;
if(!calltimes.empty())
{
// add cost to parent(caller).
tick=calltimes.top();
tick->tick += cost;
}
}
return;
}
// exception processing
void do_profile_exception(const octave_function
*fcn,profiler_function_type ftype)
{
//throw of the tos, this is corrupted.
if(!calltimes.empty())
calltimes.pop();
return;
}
void do_profile_script_return(const octave_function *fcn,
profiler_function_type ftype)
{
do_profile_return(fcn,ftype);
}
void do_profile_compiled_return(const octave_function *fcn,
profiler_function_type ftype)
{
do_profile_return(fcn,ftype);
//do_profile_return(fcn,ftype);
}
// exception processing
void do_profile_script_exception(const octave_function *fcn,
profiler_function_type ftype)
{
do_profile_exception(fcn,ftype);
}
void do_profile_compiled_exception(const octave_function *fcn,
profiler_function_type ftype)
{
do_profile_exception(fcn,ftype);
}
void profile_dispatch_func(const octave_function
*fcn,profiler_function_type ftype, profiler_call_state cstate)
{
// enter
has_profiled=true;
if( cstate == ENTER_FUNCTION )
{
switch(ftype)
{
case OCTAVE_FUNCTION:
case ANONYMOUS_FUNCTION:
case NESTED_FUNCTION:
do_profile_script_call(fcn,ftype);
break;
case BUILTIN_FUNCTION:
case MEX_FUNCTION:
do_profile_compiled_call(fcn,ftype);
break;
default:
warning("In %s @ %d : profile_dispatch_func got unknown profiling
function type\n",__FILE__,__LINE__);
}
}
// return
else if( cstate == LEAVE_FUNCTION )
{
switch(ftype)
{
case OCTAVE_FUNCTION:
case ANONYMOUS_FUNCTION:
case NESTED_FUNCTION:
do_profile_script_return(fcn,ftype);
break;
case BUILTIN_FUNCTION:
case MEX_FUNCTION:
do_profile_compiled_return(fcn,ftype);
break;
default:
warning("In %s @ %d : profile_dispatch_func got unknown profiling
function type\n",__FILE__,__LINE__);
}
}
// exception
else if( cstate == EXCEPTION_IN_FUNCTION )
{
warning("In %s @ %d : profile_dispatch_func got exception state
\n",__FILE__,__LINE__);
}
else
{
warning("In %s @ %d : profile_dispatch_func got unknown profiling call
state\n",__FILE__,__LINE__);
}
return;
}
// print_profile produces output like this,
// % cumulative self self total
// time seconds seconds calls ms/call ms/call name
// 15.71 0.11 0.11 181 0.61 0.99 RubyLex#getc
void print_profile()
{
std::list<call_elem*> call_list;
double sum=0.0;
double total=0.0;
if(!profile_flat::has_started())
{
warning("profile_flat::print_profile: no profiling done, cannot print\
the statistics\n");
return;
}
// remove handler, so the map & stack are untouched
// while we do this.
stop_profiling();
total=now(time_start);
if (total == 0.0)
total=0.01;
//sort the map values by the total-cumulative time for each function
//in ascending order. Need to load it into a list (just references)
//and then doing it at the moment.
for( std::map<std::string,call_elem *>::iterator
itr=callstats.begin(); itr !=callstats.end() ; itr++ )
{
call_elem *ptr=itr->second;
call_list.push_back(ptr);
}
//sort the list in order of increasing times.
call_list.sort();
// print out this header::
//
// % cumulative self self total
// time seconds seconds calls ms/call ms/call name
//
printf("\n");
printf(" %% cumulative self self total\n");
printf(" time seconds seconds calls ms/call ms/call name
\n");
for(std::list<call_elem *>::iterator list_itr=call_list.begin();
list_itr!=call_list.end(); list_itr++ )
{
call_elem *tmp=*list_itr;
double percent= tmp->self_time/total*100.0;
double avgcalls=tmp->self_time*1000.0/tmp->ncalls;
double avgself=tmp->total_time*1000.0/tmp->ncalls;
sum += tmp->self_time;
//
// real outputs
//
printf("%6.2f %8.2f %8.2f %8ld
",percent,sum,tmp->self_time,tmp->ncalls);
printf("%8.2f %8.2f %s\n",avgself, avgcalls, tmp->key.c_str());
}
printf("%6.2f %8.2f %8.2f %8d ",0.0,sum,0.0,1);
printf("%8.2f %8.2f %s\n",0.0,total*1e3, "#toplevel");
}
};
//initialize static members
profile_flat *profile_flat::curr_profile=static_cast<profile_flat
*>(NULL);
//entry point
DEFCMD(profile, args, ,
"-*- texinfo -*-\n\
@deftypefn {Built-in Function} {} profile (@var{name})\n\
Profile the code, and print statistics. To start profiling use\n\
profile on;\n\
... some cod .. \n\
%use any one of the following to print results & turn off\n\
profile info; %or\n\
profile off;\n\
@end deftypefn")
{
octave_value_list retval;
int nargin = args.length();
if (nargin < 1)
print_usage();
std::string cmd=args(0).string_value();
if(cmd == "on")
{
//register a hook.
profile_flat::start_profiling();
}
else if( cmd=="off" && octave_profiler::profiling )
{
// check if off called before on.
if(!profile_flat::has_started())
{
error("profile: must start profiling before \
you can turn off, or print results");
}
//stop profiling
profile_flat::stop_profiling();
}
else if( cmd=="info" )
{
// check if off called before on.
if(!profile_flat::has_started())
{
error("profile: must start profiling before \
you can turn off, or print results");
}
//stop profiling, just unhooks the register,
profile_flat::stop_profiling();
//print profiled results &
profile_flat::print_stats();
//cleanup allocated memory
profile_flat::clear_profile();
}
else
{
error("profile: must start profiling before \
you can turn off, or print results. Or cannot understand command");
}
retval(0)=octave_value(cmd);
return retval;
}
//profile.h
/*
Copyright (C) 1996, 1997 John W. Eaton
Copyright (C) 2007, Muthiah Annamalai
This file is part of Octave.
Octave is free software; you can redistribute it and/or modify it
under the terms of the GNU General Public License as published by the
Free Software Foundation; either version 2, or (at your option) any
later version.
Octave is distributed in the hope that it will be useful, but WITHOUT
ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
for more details.
You should have received a copy of the GNU General Public License
along with Octave; see the file COPYING. If not, write to the Free
Software Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
02110-1301, USA.
*/
#if !defined (octave_profiler_h)
#define octave_profiler_h 1
#include <ctime>
#include <string>
#include "comment-list.h"
#include "oct-obj.h"
#include "ov-fcn.h"
#include "ov-typeinfo.h"
class string_vector;
class octave_value;
class tree_parameter_list;
class tree_statement_list;
class tree_va_return_list;
class tree_walker;
class symbol_table;
class symbol_record;
//indicate type of function profiled
typedef enum { OCTAVE_FUNCTION, BUILTIN_FUNCTION,
ANONYMOUS_FUNCTION, MEX_FUNCTION,
NESTED_FUNCTION , ENDOF_FUNCTION_TYPES} profiler_function_type;
//indicate state of the function
typedef enum { ENTER_FUNCTION, LEAVE_FUNCTION,
EXCEPTION_IN_FUNCTION, ENDOF_FUNCTION_STATES }
profiler_call_state;
//indicate types of timers used
typedef enum { TIMER_REAL, TIMER_CPU,
TIMER_CLOCK, ENDOF_TIMER_TYPES } profiler_timer_type;
//signature of the profiler function
typedef void (*profiler_function)(const octave_function *fcn, \
profiler_function_type ftype, \
profiler_call_state cstate);
//
// convention: octave_profiler is the object/class that does the Octave
infrastructure.
// profile is the real function, that does the profiling.
//
// octave_profiler class is similar in spirit to the Python's
sys.setprofile() OR
// Ruby's set_profile_func primitives
//
class
OCTINTERP_API
octave_profiler
{
public:
//
//function used from the side of call/return sites within Octave. This
function
//passes the event to the delegated 'profile_fcn' if set. If !
profiling just
//dont do anything.
//
static void send_event(const octave_function *fcn,
profiler_function_type ftype, profiler_call_state cstate);
// return true on success, false on failure
static bool set_profiler(profiler_function profile);
// clear profiler
static bool clear_profiler();
// actual handler
static profiler_function profile_fcn;
static bool isprofiling() { return profiling; }
// indicates state of the profiler (readonly)
static bool profiling;
};
//
//The singleton class that users can derive from for creating
specialized
//profiling handlers, call-graph statistics and line/block level
granular
//profilers.
//
class
profile_base
{
//instance variables
public:
double time_start;
bool has_profiled;
virtual ~profile_base() { };
//see if singleton instance exists
static bool instance_ok() { return false; }
//factory method for singleton instance
static profile_base* get_profile(void) { return NULL; }
//start profile
static void start_profiling() { };
//stop profile only. Dont cleanup, we may print results.
static void stop_profiling() { };
//factory cleanup instance
static void clear_profile(void) { return; }
//reply if the interface has started the functions.
static bool has_started() { return false; }
//main routine to print statistics when profiling is complete
//need to get singleton instance & invoke the member method.
static void profile_base::print_stats() { return; }
//passes the static method call to the instance method, after
obtaining a singleton
//copy for this.
static void profile_func(const octave_function
*fcn,profiler_function_type ftype,\
profiler_call_state cstate)
{
return;
};
//compiled functions: Mex-file, Oct-file, Builtins
//script functions: M-file, Nested functions, Anonymous functions
//real workhorse function need to delegate the calls to various
apartments.
virtual void profile_dispatch_func(const octave_function *fcn, \
profiler_function_type ftype,
profiler_call_state cstate)=0;
//call processing
virtual void do_profile_script_call(const octave_function *fcn, \
profiler_function_type ftype)=0;
//return processing
virtual void do_profile_script_return(const octave_function *fcn, \
profiler_function_type ftype)=0;
virtual void do_profile_compiled_return(const octave_function *fcn, \
profiler_function_type ftype)=0;
// exception processing
virtual void do_profile_script_exception(const octave_function *fcn, \
profiler_function_type ftype)=0;
virtual void do_profile_compiled_exception(const octave_function *fcn,
\
profiler_function_type ftype)=0;
//print statistics actually
virtual void print_profile()=0;
};
#endif /* octave_profiler_h */
#FILE 'testprofile.m'
#------------------------------------------------------
#! /usr/bin/octave -q
function syntax_error_has()
## this doesnt define zzz, 'NameError'
## valid syntax but.
x=eig(1,zzz)
end
profile on; for ix=1:56, disp('hello');, end; profile info
##profile on; syntax_error_has ; profile info ##dont handle now
profile on
z=@(x,y) (x+y); #sum-anonymous function
y=@(x,y) (x.*y); #prod-anonymous fcn
z(1,2)
y(1,2)
z([1:10],[2:11])
z([1:10],[2:11])
z([1:10],[2:11])
y([1:10],[2:11]) # this anonymous y is different from z
y([1:10],[2:11]) # this anonymous y is different from z
y([1:10],[2:11]) # this anonymous y is different from z
profile info
profiler.cc
Description: Text Data
profiler.h
Description: Text Data
profiler_changes_cdiff.patch
Description: Text Data
testprofile.m
Description: Text Data
| [Prev in Thread] | Current Thread | [Next in Thread] |