/* 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 #endif #include "str-vec.h" #include #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 #include #include "systime.h" #include "pr-output.h" #include #include profiler_function octave_profiler::profile_fcn=static_cast(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"< Setting profiler Complete"< Setting profiler as empty profiling 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(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(0),static_cast(0)}; gettimeofday(&tv,NULL); return static_cast(tv.tv_sec) + static_cast(tv.tv_usec/1e6); } //time in seconds from last start_time, inline double now(double start_time) { struct timeval tv={static_cast(0),static_cast(0)}; gettimeofday(&tv,NULL); return static_cast(tv.tv_sec-start_time) + static_cast(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 calltimes; std::map 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(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::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(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_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::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::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(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; }