changeset: 12958:8c64cc024e8c user: Daniel Kraft date: Fri Aug 12 12:27:56 2011 +0200 files: scripts/general/profile.m description: Make hierarchical profile available via profile('info'). profile.m: Make profile('info') return also hierarchical call-tree. diff -r 43d78e103984 -r 8c64cc024e8c scripts/general/profile.m --- a/scripts/general/profile.m Fri Aug 12 12:21:48 2011 +0200 +++ b/scripts/general/profile.m Fri Aug 12 12:27:56 2011 +0200 @@ -48,9 +48,13 @@ ## ## @item @var{T} = profile ('info') ## Return the collected profiling statistics in the structure @var{T}. -## Currently, the only field is @code{FunctionTable} which is an array -## of structures, each entry corresponding to a function which was called -## and for which profiling statistics are present. +## The flat profile is returned in the field @code{FunctionTable} which is an +## array of structures, each entry corresponding to a function which was called +## and for which profiling statistics are present. Furthermore, the field +## @code{Hierarchical} contains the hierarchical call-tree. Each node +## has an index into the @code{FunctionTable} identifying the function it +## corresponds to as well as data fields for number of calls and time spent +## at this level in the call-tree. ## @end table ## @end deftypefn @@ -87,8 +91,8 @@ retval = struct ('ProfilerStatus', enabled); case 'info' - data = __profiler_data__ (); - retval = struct ('FunctionTable', data); + [flat, tree] = __profiler_data__ (); + retval = struct ('FunctionTable', flat, 'Hierarchical', tree); otherwise warning ("profile: Unrecognized option '%s'", option); changeset: 12957:43d78e103984 user: Daniel Kraft date: Fri Aug 12 12:21:48 2011 +0200 files: src/ov-builtin.cc src/ov-mex-fcn.cc src/ov-usr-fcn.cc src/profiler.h src/pt-binop.cc src/pt-unop.cc description: Use macro to start profiler blocks. profile.h: Define macros BEGIN/END_PROFILER_BLOCK. ov-builtin.cc: Use it. ov-mex-fcn.cc: Ditto. ov-usr-fcn.cc: Ditto. pt-binop.cc: Ditto. pt-unop.cc: Ditto. diff -r 332a97ea63ba -r 43d78e103984 src/ov-builtin.cc --- a/src/ov-builtin.cc Thu Aug 11 21:12:56 2011 -0500 +++ b/src/ov-builtin.cc Fri Aug 12 12:21:48 2011 +0200 @@ -126,7 +126,7 @@ try { - profile_data_accumulator::enter pe (profiler, profiler_name ()); + BEGIN_PROFILER_BLOCK (profiler_name ()) retval = (*f) (args, nargout); // Do not allow null values to be returned from functions. @@ -140,6 +140,8 @@ // the idiom is very common, so we solve that here. if (retval.length () == 1 && retval.xelem (0).is_undefined ()) retval.clear (); + + END_PROFILER_BLOCK } catch (octave_execution_exception) { diff -r 332a97ea63ba -r 43d78e103984 src/ov-mex-fcn.cc --- a/src/ov-mex-fcn.cc Thu Aug 11 21:12:56 2011 -0500 +++ b/src/ov-mex-fcn.cc Fri Aug 12 12:21:48 2011 +0200 @@ -148,8 +148,9 @@ try { - profile_data_accumulator::enter pe (profiler, profiler_name ()); + BEGIN_PROFILER_BLOCK (profiler_name ()) retval = call_mex (have_fmex, mex_fcn_ptr, args, nargout, this); + END_PROFILER_BLOCK } catch (octave_execution_exception) { diff -r 332a97ea63ba -r 43d78e103984 src/ov-usr-fcn.cc --- a/src/ov-usr-fcn.cc Thu Aug 11 21:12:56 2011 -0500 +++ b/src/ov-usr-fcn.cc Fri Aug 12 12:21:48 2011 +0200 @@ -134,11 +134,9 @@ frame.protect_var (tree_evaluator::statement_context); tree_evaluator::statement_context = tree_evaluator::script; - { - profile_data_accumulator::enter pe (profiler, - profiler_name ()); - cmd_list->accept (*current_evaluator); - } + BEGIN_PROFILER_BLOCK (profiler_name ()) + cmd_list->accept (*current_evaluator); + END_PROFILER_BLOCK if (tree_return_command::returning) tree_return_command::returning = 0; @@ -455,26 +453,26 @@ bool special_expr = (is_inline_function () || cmd_list->is_anon_function_body ()); - { - profile_data_accumulator::enter pe (profiler, profiler_name ()); + BEGIN_PROFILER_BLOCK (profiler_name ()) - if (special_expr) - { - assert (cmd_list->length () == 1); + if (special_expr) + { + assert (cmd_list->length () == 1); - tree_statement *stmt = 0; + tree_statement *stmt = 0; - if ((stmt = cmd_list->front ()) - && stmt->is_expression ()) - { - tree_expression *expr = stmt->expression (); + if ((stmt = cmd_list->front ()) + && stmt->is_expression ()) + { + tree_expression *expr = stmt->expression (); - retval = expr->rvalue (nargout); - } - } - else - cmd_list->accept (*current_evaluator); - } + retval = expr->rvalue (nargout); + } + } + else + cmd_list->accept (*current_evaluator); + + END_PROFILER_BLOCK if (echo_commands) print_code_function_trailer (); diff -r 332a97ea63ba -r 43d78e103984 src/profiler.h --- a/src/profiler.h Thu Aug 11 21:12:56 2011 -0500 +++ b/src/profiler.h Fri Aug 12 12:21:48 2011 +0200 @@ -175,4 +175,11 @@ // The instance used. extern profile_data_accumulator profiler; +// Helper macro to profile a block of code. +#define BEGIN_PROFILER_BLOCK(name) \ + { \ + profile_data_accumulator::enter pe (profiler, (name)); +#define END_PROFILER_BLOCK \ + } + #endif diff -r 332a97ea63ba -r 43d78e103984 src/pt-binop.cc --- a/src/pt-binop.cc Thu Aug 11 21:12:56 2011 -0500 +++ b/src/pt-binop.cc Fri Aug 12 12:21:48 2011 +0200 @@ -121,8 +121,7 @@ if (! error_state && b.is_defined ()) { - profile_data_accumulator::enter pe (profiler, - "binary " + oper ()); + BEGIN_PROFILER_BLOCK ("binary " + oper ()) // Note: The profiler does not catch the braindead // short-circuit evaluation code above, but that should be @@ -134,6 +133,8 @@ if (error_state) retval = octave_value (); + + END_PROFILER_BLOCK } } } diff -r 332a97ea63ba -r 43d78e103984 src/pt-unop.cc --- a/src/pt-unop.cc Thu Aug 11 21:12:56 2011 -0500 +++ b/src/pt-unop.cc Fri Aug 12 12:21:48 2011 +0200 @@ -73,13 +73,14 @@ if (! error_state) { - profile_data_accumulator::enter pe (profiler, - "prefix " + oper ()); + BEGIN_PROFILER_BLOCK ("prefix " + oper ()) ref.do_unary_op (etype); if (! error_state) retval = ref.value (); + + END_PROFILER_BLOCK } } else @@ -88,8 +89,7 @@ if (! error_state && val.is_defined ()) { - profile_data_accumulator::enter pe (profiler, - "prefix " + oper ()); + BEGIN_PROFILER_BLOCK ("prefix " + oper ()) // Attempt to do the operation in-place if it is unshared // (a temporary expression). @@ -100,6 +100,8 @@ if (error_state) retval = octave_value (); + + END_PROFILER_BLOCK } } } @@ -160,10 +162,9 @@ { retval = ref.value (); - profile_data_accumulator::enter pe (profiler, - "postfix " + oper ()); - + BEGIN_PROFILER_BLOCK ("postfix " + oper ()) ref.do_unary_op (etype); + END_PROFILER_BLOCK } } else @@ -172,13 +173,14 @@ if (! error_state && val.is_defined ()) { - profile_data_accumulator::enter pe (profiler, - "postfix " + oper ()); + BEGIN_PROFILER_BLOCK ("postfix " + oper ()) retval = ::do_unary_op (etype, val); if (error_state) retval = octave_value (); + + END_PROFILER_BLOCK } } } changeset: 12952:a451ae847adb parent: 12942:1be5f06d9fa7 user: Daniel Kraft date: Thu Aug 11 17:55:23 2011 +0200 files: src/profiler.cc src/profiler.h description: Collect hierarchical data profile. * profiler.h: Retructure whole data collection. * profiler.cc: Ditto for implementation. diff -r 1be5f06d9fa7 -r a451ae847adb src/profiler.cc --- a/src/profiler.cc Tue Aug 09 23:23:59 2011 -0400 +++ b/src/profiler.cc Thu Aug 11 17:55:23 2011 +0200 @@ -24,6 +24,7 @@ #include #endif +#include #include #include "defun.h" @@ -56,11 +57,8 @@ parents (), children () {} -// With the help of a mapping name -> index, convert a function_set list -// to an Octave array of indices. octave_value -profile_data_accumulator::stats::function_set_value (const function_set& list, - const fcn_index_map& idx) +profile_data_accumulator::stats::function_set_value (const function_set& list) { const octave_idx_type n = list.size (); @@ -68,9 +66,7 @@ octave_idx_type i = 0; for (function_set::const_iterator p = list.begin (); p != list.end (); ++p) { - fcn_index_map::const_iterator q = idx.find (*p); - assert (q != idx.end ()); - retval (i) = q->second; + retval(i) = *p; ++i; } assert (i == n); @@ -78,19 +74,144 @@ return retval; } +profile_data_accumulator::tree_node::tree_node (tree_node* p, octave_idx_type f) + : parent (p), fcn_id (f), children (), time (0.0), calls (0) +{} + +profile_data_accumulator::tree_node::~tree_node () +{ + for (child_map::iterator i = children.begin (); i != children.end (); ++i) + delete i->second; +} + +profile_data_accumulator::tree_node* +profile_data_accumulator::tree_node::enter (octave_idx_type fcn) +{ + tree_node* retval; + + child_map::iterator pos = children.find (fcn); + if (pos == children.end ()) + { + retval = new tree_node (this, fcn); + children[fcn] = retval; + } + else + retval = pos->second; + + ++retval->calls; + return retval; +} + +profile_data_accumulator::tree_node* +profile_data_accumulator::tree_node::exit (octave_idx_type fcn) +{ + assert (parent); + assert (fcn_id == fcn); + + return parent; +} + +void +profile_data_accumulator::tree_node::build_flat (flat_profile& data) const +{ + // If this is not the top-level node, update profile entry for this function. + if (fcn_id != 0) + { + stats& entry = data[fcn_id - 1]; + + entry.time += time; + entry.calls += calls; + + assert (parent); + if (parent->fcn_id != 0) + { + entry.parents.insert (parent->fcn_id); + data[parent->fcn_id - 1].children.insert (fcn_id); + } + + if (!entry.recursive) + for (const tree_node* i = parent; i; i = i->parent) + if (i->fcn_id == fcn_id) + { + entry.recursive = true; + break; + } + } + + // Recurse on children. + for (child_map::const_iterator i = children.begin (); + i != children.end (); ++i) + i->second->build_flat (data); +} + +octave_value +profile_data_accumulator::tree_node::get_hierarchical (void) const +{ + /* Note that we don't generate the entry just for this node, but rather + a struct-array with entries for all children. This way, the top-node + (for which we don't want a real entry) generates already the final + hierarchical profile data. */ + + const octave_idx_type n = children.size (); + + Cell rv_indices (n, 1); + Cell rv_times (n, 1); + Cell rv_calls (n, 1); + Cell rv_children (n, 1); + + octave_idx_type i = 0; + for (child_map::const_iterator p = children.begin (); + p != children.end (); ++p) + { + const tree_node& entry = *p->second; + + rv_indices(i) = octave_value (p->first); + rv_times(i) = octave_value (entry.time); + rv_calls(i) = octave_value (entry.calls); + rv_children(i) = entry.get_hierarchical (); + + ++i; + } + assert (i == n); + + Octave_map retval; + + retval.assign ("Index", rv_indices); + retval.assign ("SelfTime", rv_times); + retval.assign ("NumCalls", rv_calls); + retval.assign ("Children", rv_children); + + return retval; +} + profile_data_accumulator::profile_data_accumulator () - : enabled (false), call_stack (), data (), last_time (-1.0) + : known_functions (), fcn_index (), + enabled (false), call_tree (NULL), last_time (-1.0) {} +profile_data_accumulator::~profile_data_accumulator () +{ + if (call_tree) + delete call_tree; +} + void profile_data_accumulator::set_active (bool value) { - // If we enable, clear the call-stack. This ensures we freshly start - // with collecting times now. if (value) { - while (!call_stack.empty ()) - call_stack.pop_back (); + // Create a call-tree top-node if there isn't yet one. + if (!call_tree) + call_tree = new tree_node (NULL, 0); + + // Let the top-node be the active one. This ensures we have a clean + // fresh start collecting times. + active_fcn = call_tree; + } + else + { + // Make sure we start with fresh timing if we're re-enabled later. + last_time = -1.0; } enabled = value; @@ -101,39 +222,34 @@ { // The enter class will check and only call us if the profiler is active. assert (is_active ()); + assert (call_tree); // If there is already an active function, add to its time before // pushing the new one. - if (!call_stack.empty ()) + if (active_fcn != call_tree) add_current_time (); - // Update non-timing related data for the function entered. - stats& entry = data[fcn]; - ++entry.calls; - if (!call_stack.empty ()) + // Map the function's name to its index. + octave_idx_type fcn_idx; + fcn_index_map::iterator pos = fcn_index.find (fcn); + if (pos == fcn_index.end ()) { - const std::string parent_name = call_stack.back (); - entry.parents.insert (parent_name); - data[parent_name].children.insert (fcn); + known_functions.push_back (fcn); + fcn_idx = known_functions.size (); + fcn_index[fcn] = fcn_idx; } - if (!entry.recursive) - for (call_stack_type::iterator i = call_stack.begin (); - i != call_stack.end (); ++i) - if (*i == fcn) - { - entry.recursive = true; - break; - } + else + fcn_idx = pos->second; - call_stack.push_back (fcn); + active_fcn = active_fcn->enter (fcn_idx); last_time = query_time (); } void profile_data_accumulator::exit_function (const std::string& fcn) { - assert (!call_stack.empty ()); - assert (fcn == call_stack.back ()); + assert (call_tree); + assert (active_fcn != call_tree); // Usually, if we are disabled this function is not even called. But the // call disabling the profiler is an exception. So also check here @@ -141,7 +257,9 @@ if (is_active ()) add_current_time (); - call_stack.pop_back (); + fcn_index_map::iterator pos = fcn_index.find (fcn); + assert (pos != fcn_index.end ()); + active_fcn = active_fcn->exit (pos->second); // If this was an "inner call", we resume executing the parent function // up the stack. So note the start-time for this! @@ -157,26 +275,26 @@ return; } - data.clear (); + known_functions.clear (); + fcn_index.clear (); + + if (call_tree) + { + delete call_tree; + call_tree = NULL; + } + last_time = -1.0; } octave_value -profile_data_accumulator::get_data (void) const +profile_data_accumulator::get_flat (void) const { - const octave_idx_type n = data.size (); + const octave_idx_type n = known_functions.size (); - // For the parent/child data, we need to map function key-names - // to the indices they correspond to in the output array. Find them out - // in a preparation step. - fcn_index_map fcn_indices; - octave_idx_type i = 0; - for (stats_map::const_iterator p = data.begin (); p != data.end (); ++p) - { - fcn_indices[p->first] = i + 1; - ++i; - } - assert (i == n); + flat_profile flat (n); + assert (call_tree); + call_tree->build_flat (flat); Cell rv_names (n, 1); Cell rv_times (n, 1); @@ -185,21 +303,15 @@ Cell rv_parents (n, 1); Cell rv_children (n, 1); - i = 0; - for (stats_map::const_iterator p = data.begin (); p != data.end (); ++p) + for (octave_idx_type i = 0; i != n; ++i) { - const stats& entry = p->second; - - rv_names (i) = octave_value (p->first); - rv_times (i) = octave_value (entry.time); - rv_calls (i) = octave_value (entry.calls); - rv_recursive (i) = octave_value (entry.recursive); - rv_parents (i) = stats::function_set_value (entry.parents, fcn_indices); - rv_children (i) = stats::function_set_value (entry.children, fcn_indices); - - ++i; + rv_names(i) = octave_value (known_functions[i]); + rv_times(i) = octave_value (flat[i].time); + rv_calls(i) = octave_value (flat[i].calls); + rv_recursive(i) = octave_value (flat[i].recursive); + rv_parents(i) = stats::function_set_value (flat[i].parents); + rv_children(i) = stats::function_set_value (flat[i].children); } - assert (i == n); Octave_map retval; @@ -213,6 +325,13 @@ return retval; } +octave_value +profile_data_accumulator::get_hierarchical (void) const +{ + assert (call_tree); + return call_tree->get_hierarchical (); +} + double profile_data_accumulator::query_time (void) const { @@ -226,14 +345,8 @@ const double t = query_time (); assert (last_time >= 0.0 && last_time <= t); - assert (!call_stack.empty ()); - const std::string name = call_stack.back (); - - // The entry for this function should already be created; namely - // when entering the function via the non-timing data collection! - stats_map::iterator pos = data.find (name); - assert (pos != data.end ()); - pos->second.time += t - last_time; + assert (call_tree && active_fcn != call_tree); + active_fcn->add_time (t - last_time); } profile_data_accumulator profiler; @@ -283,7 +396,7 @@ } // Query the timings collected by the profiler. -DEFUN (__profiler_data, args, , +DEFUN (__profiler_data, args, nargout, "-*- texinfo -*-\n\ @deftypefn {Function File} __profiler_data ()\n\ Undocumented internal function.\n\ @@ -295,7 +408,9 @@ if (nargin > 0) warning ("profiler_data: ignoring extra arguments"); - retval(0) = profiler.get_data (); + retval(0) = profiler.get_flat (); + if (nargout > 1) + retval(1) = profiler.get_hierarchical (); return retval; } diff -r 1be5f06d9fa7 -r a451ae847adb src/profiler.h --- a/src/profiler.h Tue Aug 09 23:23:59 2011 -0400 +++ b/src/profiler.h Thu Aug 11 17:55:23 2011 +0200 @@ -40,72 +40,113 @@ // functions in a manner protected from stack unwinding. class enter { - private: + private: - profile_data_accumulator& acc; + profile_data_accumulator& acc; + std::string fcn; - std::string fcn; + public: - public: + enter (profile_data_accumulator&, const std::string&); + virtual ~enter (void); - enter (profile_data_accumulator&, const std::string&); + private: - virtual ~enter (void); - - private: - - // No copying! - - enter (const enter&); - - enter& operator = (const enter&); + // No copying! + enter (const enter&); + enter& operator = (const enter&); }; profile_data_accumulator (void); + virtual ~profile_data_accumulator (); bool is_active (void) const { return enabled; } - void set_active (bool); void reset (void); - octave_value get_data (void) const; + octave_value get_flat (void) const; + octave_value get_hierarchical (void) const; private: - typedef std::set function_set; + // One entry in the flat profile (i.e., a collection of data for a single + // function). This is filled in when building the flat profile from the + // hierarchical call tree. + struct stats + { + stats (); + + double time; + unsigned calls; + + bool recursive; + + typedef std::set function_set; + function_set parents; + function_set children; + + // Convert a function_set list to an Octave array of indices. + static octave_value function_set_value (const function_set&); + }; + + typedef std::vector flat_profile; + + // Store data for one node in the call-tree of the hierarchical profiler + // data we collect. + class tree_node + { + public: + + tree_node (tree_node*, octave_idx_type); + virtual ~tree_node (); + + void add_time (double dt) { time += dt; } + + // Enter a child function. It is created in the list of children if it + // wasn't already there. The now-active child node is returned. + tree_node* enter (octave_idx_type); + + // Exit function. As a sanity-check, it is verified that the currently + // active function actually is the one handed in here. Returned is the + // then-active node, which is our parent. + tree_node* exit (octave_idx_type); + + void build_flat (flat_profile&) const; + octave_value get_hierarchical (void) const; + + private: + + tree_node* parent; + octave_idx_type fcn_id; + + typedef std::map child_map; + child_map children; + + // This is only time spent *directly* on this level, excluding children! + double time; + + unsigned calls; + + // No copying! + tree_node (const tree_node&); + tree_node& operator = (const tree_node&); + }; + + // Each function we see in the profiler is given a unique index (which + // simply counts starting from 1). We thus have to map profiler-names to + // those indices. For all other stuff, we identify functions by their index. + + typedef std::vector function_set; typedef std::map fcn_index_map; - // Store some statistics data collected for a function. - class stats - { - private: - - double time; - unsigned calls; - - bool recursive; - - function_set parents; - function_set children; - - public: - - stats (); - - static octave_value - function_set_value (const function_set&, const fcn_index_map&); - - friend class profile_data_accumulator; - }; + function_set known_functions; + fcn_index_map fcn_index; bool enabled; - typedef std::vector call_stack_type; - call_stack_type call_stack; - - typedef std::map stats_map; - stats_map data; + tree_node* call_tree; + tree_node* active_fcn; // Store last timestamp we had, when the currently active function was called. double last_time; @@ -117,19 +158,17 @@ // Query a timestamp, used for timing calls (obviously). // This is not static because in the future, maybe we want a flag - // in the profiler or something to choose between cputime, wall-time + // in the profiler or something to choose between cputime, wall-time, // user-time, system-time, ... double query_time () const; - // Add the time elapsed since last_time to the function on the top - // of our call-stack. This is called from two different positions, - // thus it is useful to have it as a seperate function. + // Add the time elapsed since last_time to the function we're currently in. + // This is called from two different positions, thus it is useful to have + // it as a seperate function. void add_current_time (void); // No copying! - profile_data_accumulator (const profile_data_accumulator&); - profile_data_accumulator& operator = (const profile_data_accumulator&); }; changeset: 12918:5d18231eee00 parent: 12899:0ca8f06aba7a user: Daniel Kraft date: Fri Jul 29 17:51:39 2011 +0200 files: src/ov-builtin.cc src/ov-mex-fcn.cc src/ov-usr-fcn.cc src/profiler.cc src/profiler.h src/pt-binop.cc src/pt-unop.cc description: Extend profiling support to operators. * profiler.h: Always use std::string with profiler name instead of octave_function references for identifying functions. * profiler.cc: Adapt for that. * ov-builtin.cc: Ditto. * ov-mex-fcn.cc: Ditto. * ov-usr-fcn.cc: Ditto. * pt-binop.cc (tree_binary_expression::rvalue1): Collect profiler data. * pt-unop.cc (tree_prefix_expression::rvalue1): Ditto. (tree_postfix_expression::rvalue1): Ditto. diff -r 0ca8f06aba7a -r 5d18231eee00 src/ov-builtin.cc --- a/src/ov-builtin.cc Thu Jul 28 12:00:43 2011 -0400 +++ b/src/ov-builtin.cc Fri Jul 29 17:51:39 2011 +0200 @@ -126,7 +126,7 @@ try { - profile_data_accumulator::enter pe (profiler, *this); + profile_data_accumulator::enter pe (profiler, profiler_name ()); retval = (*f) (args, nargout); // Do not allow null values to be returned from functions. diff -r 0ca8f06aba7a -r 5d18231eee00 src/ov-mex-fcn.cc --- a/src/ov-mex-fcn.cc Thu Jul 28 12:00:43 2011 -0400 +++ b/src/ov-mex-fcn.cc Fri Jul 29 17:51:39 2011 +0200 @@ -148,7 +148,7 @@ try { - profile_data_accumulator::enter pe (profiler, *this); + profile_data_accumulator::enter pe (profiler, profiler_name ()); retval = call_mex (have_fmex, mex_fcn_ptr, args, nargout, this); } catch (octave_execution_exception) diff -r 0ca8f06aba7a -r 5d18231eee00 src/ov-usr-fcn.cc --- a/src/ov-usr-fcn.cc Thu Jul 28 12:00:43 2011 -0400 +++ b/src/ov-usr-fcn.cc Fri Jul 29 17:51:39 2011 +0200 @@ -135,7 +135,8 @@ tree_evaluator::statement_context = tree_evaluator::script; { - profile_data_accumulator::enter pe (profiler, *this); + profile_data_accumulator::enter pe (profiler, + profiler_name ()); cmd_list->accept (*current_evaluator); } @@ -455,7 +456,7 @@ || cmd_list->is_anon_function_body ()); { - profile_data_accumulator::enter pe (profiler, *this); + profile_data_accumulator::enter pe (profiler, profiler_name ()); if (special_expr) { diff -r 0ca8f06aba7a -r 5d18231eee00 src/profiler.cc --- a/src/profiler.cc Thu Jul 28 12:00:43 2011 -0400 +++ b/src/profiler.cc Fri Jul 29 17:51:39 2011 +0200 @@ -28,28 +28,27 @@ #include "defun.h" #include "oct-time.h" -#include "ov-fcn.h" #include "ov-struct.h" #include "pager.h" #include "profiler.h" profile_data_accumulator::enter::enter (profile_data_accumulator& a, - const octave_function& f) + const std::string& f) : acc (a) { if (acc.is_active ()) { - fcn = &f; - acc.enter_function (*fcn); + fcn = f; + acc.enter_function (fcn); } else - fcn = NULL; + fcn = ""; } profile_data_accumulator::enter::~enter () { - if (fcn) - acc.exit_function (*fcn); + if (fcn != "") + acc.exit_function (fcn); } profile_data_accumulator::stats::stats () @@ -98,7 +97,7 @@ } void -profile_data_accumulator::enter_function (const octave_function& fcn) +profile_data_accumulator::enter_function (const std::string& fcn) { // The enter class will check and only call us if the profiler is active. assert (is_active ()); @@ -109,33 +108,32 @@ add_current_time (); // Update non-timing related data for the function entered. - const std::string name = fcn.profiler_name (); - stats& entry = data[name]; + stats& entry = data[fcn]; ++entry.calls; if (!call_stack.empty ()) { - const std::string parent_name = call_stack.back ()->profiler_name (); + const std::string parent_name = call_stack.back (); entry.parents.insert (parent_name); - data[parent_name].children.insert (name); + data[parent_name].children.insert (fcn); } if (!entry.recursive) for (call_stack_type::iterator i = call_stack.begin (); i != call_stack.end (); ++i) - if (*i == &fcn) + if (*i == fcn) { entry.recursive = true; break; } - call_stack.push_back (&fcn); + call_stack.push_back (fcn); last_time = query_time (); } void -profile_data_accumulator::exit_function (const octave_function& fcn) +profile_data_accumulator::exit_function (const std::string& fcn) { assert (!call_stack.empty ()); - assert (&fcn == call_stack.back ()); + assert (fcn == call_stack.back ()); // Usually, if we are disabled this function is not even called. But the // call disabling the profiler is an exception. So also check here @@ -229,7 +227,7 @@ assert (last_time >= 0.0 && last_time <= t); assert (!call_stack.empty ()); - const std::string name = call_stack.back ()->profiler_name (); + const std::string name = call_stack.back (); // The entry for this function should already be created; namely // when entering the function via the non-timing data collection! diff -r 0ca8f06aba7a -r 5d18231eee00 src/profiler.h --- a/src/profiler.h Thu Jul 28 12:00:43 2011 -0400 +++ b/src/profiler.h Fri Jul 29 17:51:39 2011 +0200 @@ -25,9 +25,9 @@ #include #include +#include #include -class octave_function; class octave_value; class @@ -44,11 +44,11 @@ profile_data_accumulator& acc; - const octave_function* fcn; + std::string fcn; public: - enter (profile_data_accumulator&, const octave_function& fcn); + enter (profile_data_accumulator&, const std::string&); virtual ~enter (void); @@ -101,7 +101,7 @@ bool enabled; - typedef std::vector call_stack_type; + typedef std::vector call_stack_type; call_stack_type call_stack; typedef std::map stats_map; @@ -112,8 +112,8 @@ // These are private as only the unwind-protecting inner class enter // should be allowed to call them. - void enter_function (const octave_function&); - void exit_function (const octave_function&); + void enter_function (const std::string&); + void exit_function (const std::string&); // Query a timestamp, used for timing calls (obviously). // This is not static because in the future, maybe we want a flag diff -r 0ca8f06aba7a -r 5d18231eee00 src/pt-binop.cc --- a/src/pt-binop.cc Thu Jul 28 12:00:43 2011 -0400 +++ b/src/pt-binop.cc Fri Jul 29 17:51:39 2011 +0200 @@ -28,6 +28,7 @@ #include "defun.h" #include "oct-obj.h" #include "ov.h" +#include "profiler.h" #include "pt-binop.h" #include "pt-bp.h" #include "pt-walk.h" @@ -120,6 +121,12 @@ if (! error_state && b.is_defined ()) { + profile_data_accumulator::enter pe (profiler, + "binary " + oper ()); + + /* Note: The profiler does not catch the braindead-short-circuit + evaluation code above. But that should be ok. */ + retval = ::do_binary_op (etype, a, b); if (error_state) @@ -183,6 +190,11 @@ bool result = false; + /* This evaluation is not caught by the profiler, since we can't find + a reasonable place where to time. Note that we don't want to include + evaluation of LHS or RHS into the timing, but this is entangled + together with short-circuit evaluation here. */ + if (op_lhs) { octave_value a = op_lhs->rvalue1 (); diff -r 0ca8f06aba7a -r 5d18231eee00 src/pt-unop.cc --- a/src/pt-unop.cc Thu Jul 28 12:00:43 2011 -0400 +++ b/src/pt-unop.cc Fri Jul 29 17:51:39 2011 +0200 @@ -28,6 +28,7 @@ #include "oct-obj.h" #include "oct-lvalue.h" #include "ov.h" +#include "profiler.h" #include "pt-bp.h" #include "pt-unop.h" #include "pt-walk.h" @@ -72,6 +73,9 @@ if (! error_state) { + profile_data_accumulator::enter pe (profiler, + "prefix " + oper ()); + ref.do_unary_op (etype); if (! error_state) @@ -84,6 +88,9 @@ if (! error_state && val.is_defined ()) { + profile_data_accumulator::enter pe (profiler, + "prefix " + oper ()); + // Attempt to do the operation in-place if it is unshared // (a temporary expression). if (val.get_count () == 1) @@ -153,6 +160,9 @@ { retval = ref.value (); + profile_data_accumulator::enter pe (profiler, + "postfix " + oper ()); + ref.do_unary_op (etype); } } @@ -162,6 +172,9 @@ if (! error_state && val.is_defined ()) { + profile_data_accumulator::enter pe (profiler, + "postfix " + oper ()); + retval = ::do_unary_op (etype, val); if (error_state) changeset: 12887:ca5c1115b679 parent: 12876:29cd5a828bb2 user: Daniel Kraft date: Mon Jul 25 11:24:18 2011 +0200 files: scripts/general/profshow.m description: Show recursive-flag of functions in profshow. * profshow.m: Add attribute column to display table, which shows the recursive flag of function data. diff -r 29cd5a828bb2 -r ca5c1115b679 scripts/general/profshow.m --- a/scripts/general/profshow.m Sat Jul 23 19:25:03 2011 -0700 +++ b/scripts/general/profshow.m Mon Jul 25 11:24:18 2011 +0200 @@ -27,6 +27,9 @@ ## sorted in descending order by total time spent in them. If there are more ## than @var{n} included in the profile, those will not be shown. @var{n} ## defaults to 20. +## +## The attribute column shows @samp{R} for recursive functions and nothing +## otherwise. ## @end deftypefn ## Built-in profiler. @@ -60,19 +63,22 @@ for i = 1 : n nameLen = max (nameLen, length (data.FunctionTable(p(i)).FunctionName)); endfor - headerFormat = sprintf ('%%%ds %%12s %%12s\n', nameLen); - rowFormat = sprintf ('%%%ds%%13.3f%%13d\n', nameLen); + headerFormat = sprintf ('%%%ds %%4s %%12s %%12s\n', nameLen); + rowFormat = sprintf ('%%%ds %%4s %%12.3f %%12d\n', nameLen); - printf (headerFormat, 'Function', 'Time (s)', 'Calls'); - printf ("%s\n", repmat ('-', 1, nameLen + 2 * 13)); + printf (headerFormat, 'Function', 'Attr', 'Time (s)', 'Calls'); + printf ("%s\n", repmat ('-', 1, nameLen + 2 * 13 + 5)); for i = 1 : n row = data.FunctionTable(p(i)); - printf (rowFormat, row.FunctionName, row.TotalTime, row.NumCalls); + attr = ''; + if (row.IsRecursive) + attr = 'R'; + endif + printf (rowFormat, row.FunctionName, attr, row.TotalTime, row.NumCalls); endfor endfunction - %!demo %! profile ('on'); %! A = rand (100); @@ -80,3 +86,16 @@ %! profile ('off'); %! T = profile ('info'); %! profshow (T, 10); + +%!demo +%! function f = myfib (n) +%! if (n <= 2) +%! f = 1; +%! else +%! f = myfib (n - 1) + myfib (n - 2); +%! endif +%! endfunction +%! profile ('on'); +%! myfib (20); +%! profile ('off'); +%! profshow (profile ('info'), 5); changeset: 12871:23377c46516b user: Daniel Kraft date: Wed Jul 20 18:33:42 2011 +0200 files: scripts/general/module.mk scripts/general/profile.m scripts/general/profshow.m description: Implement the profshow function to print profiler results. * module.mk: Add profshow.m as new file. * profile.m: Use profshow in demo. * profshow.m: New function/file. diff -r 39d813616c8f -r 23377c46516b scripts/general/module.mk --- a/scripts/general/module.mk Fri Jul 22 00:57:38 2011 -0500 +++ b/scripts/general/module.mk Wed Jul 20 18:33:42 2011 +0200 @@ -62,6 +62,7 @@ general/postpad.m \ general/prepad.m \ general/profile.m \ + general/profshow.m \ general/quadgk.m \ general/quadl.m \ general/quadv.m \ diff -r 39d813616c8f -r 23377c46516b scripts/general/profile.m --- a/scripts/general/profile.m Fri Jul 22 00:57:38 2011 -0500 +++ b/scripts/general/profile.m Wed Jul 20 18:33:42 2011 +0200 @@ -100,4 +100,5 @@ %! profile ('resume'); %! C = sqrtm (A); %! profile ('off'); -%! T = profile ('info') +%! T = profile ('info'); +%! profshow (T); diff -r 39d813616c8f -r 23377c46516b scripts/general/profshow.m --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/scripts/general/profshow.m Wed Jul 20 18:33:42 2011 +0200 @@ -0,0 +1,81 @@ +## Copyright (C) 2011 Daniel Kraft +## +## 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 3 of the License, 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, see +## . + +## -*- texinfo -*- +## @deftypefn {Function File} {} profshow (@var{data}) +## @deftypefnx {Function File} {} profshow (@var{data}, @var{n}) +## Show flat profiler results. +## +## This command prints out profiler data as a flat profile. @var{data} is the +## structure returned by @code{profile ('info')}. If @var{n} is given, it +## specifies the number of functions to show in the profile; functions are +## sorted in descending order by total time spent in them. If there are more +## than @var{n} included in the profile, those will not be shown. @var{n} +## defaults to 20. +## @end deftypefn + +## Built-in profiler. +## Author: Daniel Kraft + +function profshow (data, n) + + if (nargin < 2) + n = 20; + endif + + m = length (data.FunctionTable); + n = min (n, m); + + % We want to sort by times in descending order. For this, extract the + % times to an array, then sort this, and use the resulting index permutation + % to print out our table. + times = NA (1, m); + for i = 1 : m + times(i) = - data.FunctionTable(i).TotalTime; + endfor + [~, p] = sort (times); + + % For printing the table, find out the maximum length of a function name + % so that we can proportion the table accordingly. Based on this, + % we can build the format used for printing table rows. + nameLen = length ('Function'); + for i = 1 : n + nameLen = max (nameLen, length (data.FunctionTable(p(i)).FunctionName)); + endfor + headerFormat = sprintf ('%%%ds %%12s %%12s\n', nameLen); + rowFormat = sprintf ('%%%ds%%13.3f%%13d\n', nameLen); + + printf (headerFormat, 'Function', 'Time (s)', 'Calls'); + for i = 1 : nameLen + 2 * 13 + printf ('-'); + endfor + printf ('\n'); + for i = 1 : n + row = data.FunctionTable(p(i)); + printf (rowFormat, row.FunctionName, row.TotalTime, row.NumCalls); + endfor + +endfunction + +%!demo +%! profile ('on'); +%! A = rand (100); +%! B = expm (A); +%! profile ('off'); +%! T = profile ('info'); +%! profshow (T, 10); changeset: 12869:de9a9719e594 user: Daniel Kraft date: Thu Jul 14 22:16:24 2011 +0200 files: scripts/general/module.mk scripts/general/profile.m src/profiler.cc src/profiler.h description: Extend data collection in profiler and add user-interface profile function. * scripts/general/module.mk: Add profile.m. * scripts/general/profile.m: New file. * src/profiler.h (stats): New utility class. (data): Field to replace old times, can now hold more info. * src/profiler.cc (stats): Implementation of routines. (profile_data_accumulator): Changes necessary because call_stack was changed to be a std::vector now and for the new statistics map. (profile_data_accumulator::get_data): Extended to produce much more sophisticated output. (profile_data_accumulator::enter_function): Collect some more data than the timing. diff -r b00181c65533 -r de9a9719e594 scripts/general/module.mk --- a/scripts/general/module.mk Fri Jul 22 13:15:00 2011 -0700 +++ b/scripts/general/module.mk Thu Jul 14 22:16:24 2011 +0200 @@ -61,6 +61,7 @@ general/polyarea.m \ general/postpad.m \ general/prepad.m \ + general/profile.m \ general/quadgk.m \ general/quadl.m \ general/quadv.m \ diff -r b00181c65533 -r de9a9719e594 scripts/general/profile.m --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/scripts/general/profile.m Thu Jul 14 22:16:24 2011 +0200 @@ -0,0 +1,103 @@ +## Copyright (C) 2011 Daniel Kraft +## +## 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 3 of the License, 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, see +## . + +## -*- texinfo -*- +## @deftypefn {Function File} {} profile on +## @deftypefnx {Function File} {} profile off +## @deftypefnx {Function File} {} profile resume +## @deftypefnx {Function File} {} profile clear +## @deftypefnx {Function File} address@hidden =} profile ('status') +## @deftypefnx {Function File} address@hidden =} profile ('info') +## Control the built-in profiler. +## +## @table @code +## @item profile on +## Start the profiler, clearing all previously collected data if there +## is any. +## +## @item profile off +## Stop profiling. The collected data can later be retrieved and examined +## with calls like @code{S = profile ('info')}. +## +## @item profile clear +## Clear all collected profiler data. +## +## @item profile resume +## Restart profiling without cleaning up the old data and instead +## all newly collected statistics are added to the already existing ones. +## +## @item @var{S} = profile ('status') +## Return a structure filled with certain information about the current status +## of the profiler. At the moment, the only field is @code{ProfilerStatus} +## which is either 'on' or 'off'. +## +## @item @var{T} = profile ('info') +## Return the collected profiling statistics in the structure @var{T}. +## Currently, the only field is @code{FunctionTable} which is an array +## of structures, each entry corresponding to a function which was called +## and for which profiling statistics are present. +## @end table +## @end deftypefn + +## Built-in profiler. +## Author: Daniel Kraft + +function retval = profile (option) + + switch (option) + case 'on' + __profiler_reset (); + __profiler_enable (true); + + case 'off' + __profiler_enable (false); + + case 'clear' + __profiler_reset (); + + case 'resume' + __profiler_enable (true); + + case 'status' + enabled = __profiler_enable (); + if (enabled) + enabled = 'on'; + else + enabled = 'off'; + endif + retval = struct ('ProfilerStatus', enabled); + + case 'info' + data = __profiler_data (); + retval = struct ('FunctionTable', data); + + otherwise + print_usage (); + endswitch + +endfunction + +%!demo +%! profile ('on'); +%! A = rand (100); +%! B = expm (A); +%! profile ('off'); +%! profile ('resume'); +%! C = sqrtm (A); +%! profile ('off'); +%! T = profile ('info') diff -r b00181c65533 -r de9a9719e594 src/profiler.cc --- a/src/profiler.cc Fri Jul 22 13:15:00 2011 -0700 +++ b/src/profiler.cc Thu Jul 14 22:16:24 2011 +0200 @@ -26,7 +26,6 @@ #include -#include "Cell.h" #include "defun.h" #include "oct-time.h" #include "ov-fcn.h" @@ -53,8 +52,35 @@ acc.exit_function (*fcn); } +profile_data_accumulator::stats::stats () + : time (0.0), calls (0), recursive (false), + parents (), children () +{} + +// With the help of a mapping name -> index, convert a function_set list +// to an Octave array of indices. +octave_value +profile_data_accumulator::stats::function_set_value (const function_set& list, + const fcn_index_map& idx) +{ + const octave_idx_type n = list.size (); + + RowVector retval (n); + octave_idx_type i = 0; + for (function_set::const_iterator p = list.begin (); p != list.end (); ++p) + { + fcn_index_map::const_iterator q = idx.find (*p); + assert (q != idx.end ()); + retval (i) = q->second; + ++i; + } + assert (i == n); + + return retval; +} + profile_data_accumulator::profile_data_accumulator () - : enabled (false), call_stack (), times (), last_time (-1.0) + : enabled (false), call_stack (), data (), last_time (-1.0) {} void @@ -65,7 +91,7 @@ if (value) { while (!call_stack.empty ()) - call_stack.pop (); + call_stack.pop_back (); } enabled = value; @@ -82,7 +108,26 @@ if (!call_stack.empty ()) add_current_time (); - call_stack.push (&fcn); + // Update non-timing related data for the function entered. + const std::string name = fcn.profiler_name (); + stats& entry = data[name]; + ++entry.calls; + if (!call_stack.empty ()) + { + const std::string parent_name = call_stack.back ()->profiler_name (); + entry.parents.insert (parent_name); + data[parent_name].children.insert (name); + } + if (!entry.recursive) + for (call_stack_type::iterator i = call_stack.begin (); + i != call_stack.end (); ++i) + if (*i == &fcn) + { + entry.recursive = true; + break; + } + + call_stack.push_back (&fcn); last_time = query_time (); } @@ -90,7 +135,7 @@ profile_data_accumulator::exit_function (const octave_function& fcn) { assert (!call_stack.empty ()); - assert (&fcn == call_stack.top ()); + assert (&fcn == call_stack.back ()); // Usually, if we are disabled this function is not even called. But the // call disabling the profiler is an exception. So also check here @@ -98,7 +143,7 @@ if (is_active ()) add_current_time (); - call_stack.pop (); + call_stack.pop_back (); // If this was an "inner call", we resume executing the parent function // up the stack. So note the start-time for this! @@ -114,28 +159,59 @@ return; } - times.clear (); + data.clear (); last_time = -1.0; } -Cell +octave_value profile_data_accumulator::get_data (void) const { - const int n = times.size (); + const octave_idx_type n = data.size (); - Cell retval (1, n); - int i = 0; - for (timing_map::const_iterator p = times.begin (); p != times.end (); ++p) + // For the parent/child data, we need to map function key-names + // to the indices they correspond to in the output array. Find them out + // in a preparation step. + fcn_index_map fcn_indices; + octave_idx_type i = 0; + for (stats_map::const_iterator p = data.begin (); p != data.end (); ++p) { - octave_scalar_map entry; - - entry.contents ("name") = octave_value (p->first); - entry.contents ("time") = octave_value (p->second); - - retval (i++) = entry; + fcn_indices[p->first] = i + 1; + ++i; } assert (i == n); + Cell rv_names (n, 1); + Cell rv_times (n, 1); + Cell rv_calls (n, 1); + Cell rv_recursive (n, 1); + Cell rv_parents (n, 1); + Cell rv_children (n, 1); + + i = 0; + for (stats_map::const_iterator p = data.begin (); p != data.end (); ++p) + { + const stats& entry = p->second; + + rv_names (i) = octave_value (p->first); + rv_times (i) = octave_value (entry.time); + rv_calls (i) = octave_value (entry.calls); + rv_recursive (i) = octave_value (entry.recursive); + rv_parents (i) = stats::function_set_value (entry.parents, fcn_indices); + rv_children (i) = stats::function_set_value (entry.children, fcn_indices); + + ++i; + } + assert (i == n); + + Octave_map retval; + + retval.assign ("FunctionName", rv_names); + retval.assign ("TotalTime", rv_times); + retval.assign ("NumCalls", rv_calls); + retval.assign ("IsRecursive", rv_recursive); + retval.assign ("Parents", rv_parents); + retval.assign ("Children", rv_children); + return retval; } @@ -153,19 +229,21 @@ assert (last_time >= 0.0 && last_time <= t); assert (!call_stack.empty ()); - const std::string name = call_stack.top ()->profiler_name (); + const std::string name = call_stack.back ()->profiler_name (); - // If the key is not yet present in the map, it is constructed - // with default value 0. - times[name] += t - last_time; + // The entry for this function should already be created; namely + // when entering the function via the non-timing data collection! + stats_map::iterator pos = data.find (name); + assert (pos != data.end ()); + pos->second.time += t - last_time; } profile_data_accumulator profiler; -DEFUN (profiler_enable, args, nargout, +DEFUN (__profiler_enable, args, , "-*- texinfo -*-\n\ address@hidden {Built-in Function} {} profiler_enable (enabled)\n\ -Enable or disable the profiler data collection.\n\ address@hidden {Function File} __profiler_enable ()\n\ +Undocumented internal function.\n\ @end deftypefn") { octave_value_list retval; @@ -187,10 +265,10 @@ return retval; } -DEFUN (profiler_reset, args, nargout, +DEFUN (__profiler_reset, args, , "-*- texinfo -*-\n\ address@hidden {Built-in Function} {} profiler_reset ()\n\ -Clear all collected profiling data.\n\ address@hidden {Function File} __profiler_reset ()\n\ +Undocumented internal function.\n\ @end deftypefn") { octave_value_list retval; @@ -204,10 +282,10 @@ return retval; } -DEFUN (profiler_data, args, nargout, +DEFUN (__profiler_data, args, , "-*- texinfo -*-\n\ address@hidden {Built-in Function} {} data = profiler_data ()\n\ -Query the timings collected by the profiler.\n\ address@hidden {Function File} __profiler_data ()\n\ +Undocumented internal function.\n\ @end deftypefn") { octave_value_list retval; diff -r b00181c65533 -r de9a9719e594 src/profiler.h --- a/src/profiler.h Fri Jul 22 13:15:00 2011 -0700 +++ b/src/profiler.h Thu Jul 14 22:16:24 2011 +0200 @@ -23,11 +23,12 @@ #if !defined (octave_profiler_h) #define octave_profiler_h 1 -#include #include +#include +#include class octave_function; -class Cell; +class octave_value; class OCTAVE_API @@ -68,16 +69,43 @@ void reset (void); - Cell get_data (void) const; + octave_value get_data (void) const; private: + typedef std::set function_set; + typedef std::map fcn_index_map; + + // Store some statistics data collected for a function. + class stats + { + private: + + double time; + unsigned calls; + + bool recursive; + + function_set parents; + function_set children; + + public: + + stats (); + + static octave_value + function_set_value (const function_set&, const fcn_index_map&); + + friend class profile_data_accumulator; + }; + bool enabled; - std::stack call_stack; + typedef std::vector call_stack_type; + call_stack_type call_stack; - typedef std::map timing_map; - timing_map times; + typedef std::map stats_map; + stats_map data; // Store last timestamp we had, when the currently active function was called. double last_time; changeset: 12779:ad9263d965dc user: Daniel Kraft date: Thu Jun 30 20:04:34 2011 +0200 files: src/Makefile.am src/oct-parse.yy src/ov-builtin.cc src/ov-fcn.h src/ov-mex-fcn.cc src/ov-usr-fcn.cc src/ov-usr-fcn.h src/profiler.cc src/profiler.h src/pt-fcn-handle.cc description: First experimental profiler implementation with flat profile. * profiler.cc: New file. * profiler.h: New file. * Makefile.am: Include new files in build process. * oct-parse.yy (frob_function): Store location of function parsed. * ov-fcn.h (octave_function::profiler_name): New method. * ov-builtin.cc (octave_builtin::do_multi_index_op): Record timings in profiler. * ov-mex-fcn.cc (octave_mex_function::do_multi_index_op): Ditto. * ov-usr-fcn.cc (octave_user_script::do_multi_index_op): Ditto. (octave_user_function::do_multi_index_op): Ditto. (octave_user_function::octave_user_function): Initialize location_line/column. (octave_user_function::profiler_name): New method. * ov-usr-fcn.h (octave_user_function): New variables location_line, location column and new method stash_fcn_location to set them. * pt-fcn-handle.cc (tree_anon_fcn_handle::rvalue1): Store location. diff -r 0ca5672d5f1a -r ad9263d965dc src/Makefile.am --- a/src/Makefile.am Thu Jul 07 19:16:14 2011 -0400 +++ b/src/Makefile.am Thu Jun 30 20:04:34 2011 +0200 @@ -310,6 +310,7 @@ defaults.h \ graphics.h \ oct-conf.h \ + profiler.h \ mxarray.h \ version.h @@ -446,6 +447,7 @@ pager.cc \ pr-output.cc \ procstream.cc \ + profiler.cc \ sighandlers.cc \ siglist.c \ sparse.cc \ diff -r 0ca5672d5f1a -r ad9263d965dc src/oct-parse.yy --- a/src/oct-parse.yy Thu Jul 07 19:16:14 2011 -0400 +++ b/src/oct-parse.yy Thu Jun 30 20:04:34 2011 +0200 @@ -2900,6 +2900,7 @@ } fcn->stash_function_name (id_name); + fcn->stash_fcn_location (input_line_number, current_input_column); if (! help_buf.empty () && current_function_depth == 1 && ! parsing_subfunctions) diff -r 0ca5672d5f1a -r ad9263d965dc src/ov-builtin.cc --- a/src/ov-builtin.cc Thu Jul 07 19:16:14 2011 -0400 +++ b/src/ov-builtin.cc Thu Jun 30 20:04:34 2011 +0200 @@ -29,6 +29,7 @@ #include "oct-obj.h" #include "ov-builtin.h" #include "ov.h" +#include "profiler.h" #include "toplev.h" #include "unwind-prot.h" @@ -125,6 +126,8 @@ try { + profile_data_accumulator::enter pe (profiler, *this); + retval = (*f) (args, nargout); // Do not allow null values to be returned from functions. // FIXME -- perhaps true builtins should be allowed? diff -r 0ca5672d5f1a -r ad9263d965dc src/ov-fcn.h --- a/src/ov-fcn.h Thu Jul 07 19:16:14 2011 -0400 +++ b/src/ov-fcn.h Thu Jun 30 20:04:34 2011 +0200 @@ -60,6 +60,9 @@ virtual bool is_system_fcn_file (void) const { return false; } virtual std::string fcn_file_name (void) const { return std::string (); } + + // The name to show in the profiler (also used as map-key). + virtual std::string profiler_name (void) const { return name (); } virtual std::string parent_fcn_name (void) const { return std::string (); } diff -r 0ca5672d5f1a -r ad9263d965dc src/ov-mex-fcn.cc --- a/src/ov-mex-fcn.cc Thu Jul 07 19:16:14 2011 -0400 +++ b/src/ov-mex-fcn.cc Thu Jun 30 20:04:34 2011 +0200 @@ -33,6 +33,7 @@ #include "oct-obj.h" #include "ov-mex-fcn.h" #include "ov.h" +#include "profiler.h" #include "toplev.h" #include "unwind-prot.h" @@ -147,6 +148,7 @@ try { + profile_data_accumulator::enter pe (profiler, *this); retval = call_mex (have_fmex, mex_fcn_ptr, args, nargout, this); } catch (octave_execution_exception) diff -r 0ca5672d5f1a -r ad9263d965dc src/ov-usr-fcn.cc --- a/src/ov-usr-fcn.cc Thu Jul 07 19:16:14 2011 -0400 +++ b/src/ov-usr-fcn.cc Thu Jun 30 20:04:34 2011 +0200 @@ -24,6 +24,8 @@ #include #endif +#include + #include "str-vec.h" #include @@ -47,6 +49,7 @@ #include "unwind-prot.h" #include "utils.h" #include "parse.h" +#include "profiler.h" #include "variables.h" // Whether to optimize subsasgn method calls. @@ -131,7 +134,10 @@ frame.protect_var (tree_evaluator::statement_context); tree_evaluator::statement_context = tree_evaluator::script; - cmd_list->accept (*current_evaluator); + { + profile_data_accumulator::enter pe (profiler, *this); + cmd_list->accept (*current_evaluator); + } if (tree_return_command::returning) tree_return_command::returning = 0; @@ -176,6 +182,7 @@ : octave_user_code (std::string (), std::string ()), param_list (pl), ret_list (rl), cmd_list (cl), lead_comm (), trail_comm (), file_name (), + location_line (0), location_column (0), parent_name (), t_parsed (static_cast (0)), t_checked (static_cast (0)), system_fcn_file (false), call_depth (-1), @@ -217,6 +224,22 @@ file_name = nm; } +std::string +octave_user_function::profiler_name (void) const +{ + std::ostringstream result; + + if (is_inline_function ()) + result << "anonymous@" << fcn_file_name () + << ":" << location_line << ":" << location_column; + else if (is_subfunction ()) + result << parent_fcn_name () << ">" << name (); + else + result << name (); + + return result.str (); +} + void octave_user_function::mark_as_system_fcn_file (void) { @@ -431,22 +454,26 @@ bool special_expr = (is_inline_function () || cmd_list->is_anon_function_body ()); - if (special_expr) - { - assert (cmd_list->length () == 1); + { + profile_data_accumulator::enter pe (profiler, *this); - tree_statement *stmt = 0; + if (special_expr) + { + assert (cmd_list->length () == 1); - if ((stmt = cmd_list->front ()) - && stmt->is_expression ()) - { - tree_expression *expr = stmt->expression (); + tree_statement *stmt = 0; - retval = expr->rvalue (nargout); - } - } - else - cmd_list->accept (*current_evaluator); + if ((stmt = cmd_list->front ()) + && stmt->is_expression ()) + { + tree_expression *expr = stmt->expression (); + + retval = expr->rvalue (nargout); + } + } + else + cmd_list->accept (*current_evaluator); + } if (echo_commands) print_code_function_trailer (); diff -r 0ca5672d5f1a -r ad9263d965dc src/ov-usr-fcn.h --- a/src/ov-usr-fcn.h Thu Jul 07 19:16:14 2011 -0400 +++ b/src/ov-usr-fcn.h Thu Jun 30 20:04:34 2011 +0200 @@ -189,6 +189,12 @@ void stash_fcn_file_name (const std::string& nm); + void stash_fcn_location (int line, int col) + { + location_line = line; + location_column = col; + } + void stash_parent_fcn_name (const std::string& p) { parent_name = p; } void stash_parent_fcn_scope (symbol_table::scope_id ps) { parent_scope = ps; } @@ -207,6 +213,8 @@ std::string fcn_file_name (void) const { return file_name; } + std::string profiler_name (void) const; + std::string parent_fcn_name (void) const { return parent_name; } symbol_table::scope_id parent_fcn_scope (void) const { return parent_scope; } @@ -344,6 +352,10 @@ // The name of the file we parsed. std::string file_name; + // Location where this function was defined. + int location_line; + int location_column; + // The name of the parent function, if any. std::string parent_name; diff -r 0ca5672d5f1a -r ad9263d965dc src/profiler.cc --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/src/profiler.cc Thu Jun 30 20:04:34 2011 +0200 @@ -0,0 +1,231 @@ +/* + +Copyright (C) 2011 Daniel Kraft + +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 3 of the License, 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, see +. + +*/ + +#ifdef HAVE_CONFIG_H +#include +#endif + +#include + +#include "Cell.h" +#include "defun.h" +#include "oct-time.h" +#include "ov-fcn.h" +#include "ov-struct.h" +#include "pager.h" +#include "profiler.h" + +profile_data_accumulator::enter::enter (profile_data_accumulator& a, + const octave_function& f) + : acc (a) +{ + if (acc.is_active ()) + { + fcn = &f; + acc.enter_function (*fcn); + } + else + fcn = NULL; +} + +profile_data_accumulator::enter::~enter () +{ + if (fcn) + acc.exit_function (*fcn); +} + +profile_data_accumulator::profile_data_accumulator () + : enabled (false), call_stack (), times (), last_time (-1.0) +{} + +void +profile_data_accumulator::set_active (bool value) +{ + // If we enable, clear the call-stack. This ensures we freshly start + // with collecting times now. + if (value) + { + while (!call_stack.empty ()) + call_stack.pop (); + } + + enabled = value; +} + +void +profile_data_accumulator::enter_function (const octave_function& fcn) +{ + // The enter class will check and only call us if the profiler is active. + assert (is_active ()); + + // If there is already an active function, add to its time before + // pushing the new one. + if (!call_stack.empty ()) + add_current_time (); + + call_stack.push (&fcn); + last_time = query_time (); +} + +void +profile_data_accumulator::exit_function (const octave_function& fcn) +{ + assert (!call_stack.empty ()); + assert (&fcn == call_stack.top ()); + + // Usually, if we are disabled this function is not even called. But the + // call disabling the profiler is an exception. So also check here + // and only record the time if enabled. + if (is_active ()) + add_current_time (); + + call_stack.pop (); + + // If this was an "inner call", we resume executing the parent function + // up the stack. So note the start-time for this! + last_time = query_time (); +} + +void +profile_data_accumulator::reset (void) +{ + if (is_active ()) + { + error ("Can't reset active profiler."); + return; + } + + times.clear (); + last_time = -1.0; +} + +Cell +profile_data_accumulator::get_data (void) const +{ + const int n = times.size (); + + Cell result (1, n); + int i = 0; + for (timing_map::const_iterator p = times.begin (); p != times.end (); ++p) + { + octave_scalar_map entry; + + entry.contents ("name") = octave_value (p->first); + entry.contents ("time") = octave_value (p->second); + + result (i++) = entry; + } + assert (i == n); + + return result; +} + +double +profile_data_accumulator::query_time (void) const +{ + octave_time now; + return now.double_value (); +} + +void +profile_data_accumulator::add_current_time (void) +{ + const double t = query_time (); + assert (last_time >= 0.0 && last_time <= t); + + assert (!call_stack.empty ()); + const std::string name = call_stack.top ()->profiler_name (); + + // If the key is not yet present in the map, it is constructed + // with default value 0. + times[name] += t - last_time; +} + +profile_data_accumulator profiler; + +DEFUN (profiler_enable, args, nargout, + "-*- texinfo -*-\n\ address@hidden {Built-in Function} {} profiler_enable (enabled)\n\ +Enable or disable the profiler data collection.\n\ address@hidden deftypefn") +{ + // If there is an output argument, return current (if we change the old) + // status of the profiler. + octave_value_list result; + if (nargout > 0) + { + if (nargout > 1) + error ("profiler_enable: too many output arguments requested"); + + result(0) = profiler.is_active (); + } + + // If there is an input argument, set the status. + const int nargin = args.length (); + if (nargin > 0) + { + if (nargin > 1) + error ("profiler_enable: too many arguments specified"); + + profiler.set_active (args(0).bool_value ()); + } + + return result; +} + +DEFUN (profiler_reset, args, nargout, + "-*- texinfo -*-\n\ address@hidden {Built-in Function} {} profiler_reset ()\n\ +Clear all collected profiling data.\n\ address@hidden deftypefn") +{ + octave_value_list result; + const int nargin = args.length (); + + if (nargin > 0) + error ("profiler_reset: no arguments expected"); + if (nargout > 0) + error ("profiler_reset: no output argument possible"); + + profiler.reset (); + + return result; +} + +DEFUN (profiler_data, args, nargout, + "-*- texinfo -*-\n\ address@hidden {Built-in Function} {} data = profiler_data ()\n\ +Query the timings collected by the profiler.\n\ address@hidden deftypefn") +{ + octave_value_list result; + const int nargin = args.length (); + + if (nargin > 0) + error ("profiler_data: no arguments expected"); + if (nargout != 1) + error ("profiler_reset: expected exactly one output argument"); + + result(0) = profiler.get_data (); + + return result; +} diff -r 0ca5672d5f1a -r ad9263d965dc src/profiler.h --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/src/profiler.h Thu Jun 30 20:04:34 2011 +0200 @@ -0,0 +1,111 @@ +/* + +Copyright (C) 2011 Daniel Kraft + +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 3 of the License, 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, see +. + +*/ + +#if !defined (octave_profiler_h) +#define octave_profiler_h 1 + +#include +#include + +class octave_function; +class Cell; + +class +OCTAVE_API +profile_data_accumulator +{ +public: + + // This is a utility class that can be used to call the enter/exit + // functions in a manner protected from stack unwinding. + class enter + { + private: + + profile_data_accumulator& acc; + + const octave_function* fcn; + + public: + + enter (profile_data_accumulator&, const octave_function& fcn); + + virtual ~enter (void); + + private: + + // No copying! + + enter (const enter&); + + enter& operator = (const enter&); + }; + + profile_data_accumulator (void); + + bool is_active (void) const { return enabled; } + + void set_active (bool); + + void reset (void); + + Cell get_data (void) const; + +private: + + bool enabled; + + std::stack call_stack; + + typedef std::map timing_map; + timing_map times; + + // Store last timestamp we had, when the currently active function was called. + double last_time; + + // These are private as only the unwind-protecting inner class enter + // should be allowed to call them. + void enter_function (const octave_function&); + void exit_function (const octave_function&); + + // Query a timestamp, used for timing calls (obviously). + // This is not static because in the future, maybe we want a flag + // in the profiler or something to choose between cputime, wall-time + // user-time, system-time, ... + double query_time () const; + + // Add the time elapsed since last_time to the function on the top + // of our call-stack. This is called from two different positions, + // thus it is useful to have it as a seperate function. + void add_current_time (void); + + // No copying! + + profile_data_accumulator (const profile_data_accumulator&); + + profile_data_accumulator& operator = (const profile_data_accumulator&); +}; + +// The instance used. +extern profile_data_accumulator profiler; + +#endif diff -r 0ca5672d5f1a -r ad9263d965dc src/pt-fcn-handle.cc --- a/src/pt-fcn-handle.cc Thu Jul 07 19:16:14 2011 -0400 +++ b/src/pt-fcn-handle.cc Thu Jun 30 20:04:34 2011 +0200 @@ -127,6 +127,7 @@ } uf->mark_as_inline_function (); + uf->stash_fcn_location (line (), column ()); octave_value ov_fcn (uf); changeset: 12651:332bb3b9600e user: Daniel Kraft date: Fri May 06 18:38:30 2011 -0400 files: src/variables.cc description: interpreter: Add new attribute 'complex' in whos (bug #32053) * variables.cc (symbol_info_list::symbol_info::is_complex): New attribute. (symbol_info_list::symbol_info::display_line): Print complex attribute. (symbol_info_list::parse_whos_line_format): Reserve space for attribute column. (Fwhos): Document new complex attribute. diff -r b7f16997df4d -r 332bb3b9600e src/variables.cc --- a/src/variables.cc Fri May 06 09:39:08 2011 -0700 +++ b/src/variables.cc Fri May 06 18:38:30 2011 -0400 @@ -1043,11 +1043,12 @@ const std::string& expr_str = std::string (), const octave_value& expr_val = octave_value ()) : name (expr_str.empty () ? sr.name () : expr_str), + varval (expr_val.is_undefined () ? sr.varval () : expr_val), is_automatic (sr.is_automatic ()), + is_complex (varval.is_complex_type ()), is_formal (sr.is_formal ()), is_global (sr.is_global ()), - is_persistent (sr.is_persistent ()), - varval (expr_val.is_undefined () ? sr.varval () : expr_val) + is_persistent (sr.is_persistent ()) { } void display_line (std::ostream& os, @@ -1117,13 +1118,14 @@ { case 'a': { - char tmp[5]; + char tmp[6]; tmp[0] = (is_automatic ? 'a' : ' '); - tmp[1] = (is_formal ? 'f' : ' '); - tmp[2] = (is_global ? 'g' : ' '); - tmp[3] = (is_persistent ? 'p' : ' '); - tmp[4] = 0; + tmp[1] = (is_complex ? 'c' : ' '); + tmp[2] = (is_formal ? 'f' : ' '); + tmp[3] = (is_global ? 'g' : ' '); + tmp[4] = (is_persistent ? 'p' : ' '); + tmp[5] = 0; os << tmp; } @@ -1172,11 +1174,12 @@ } std::string name; + octave_value varval; bool is_automatic; + bool is_complex; bool is_formal; bool is_global; bool is_persistent; - octave_value varval; }; public: @@ -1333,6 +1336,9 @@ for (size_t i = 0; i < param_string.length (); i++) param_length(i) = param_names(i) . length (); + // The attribute column needs size 5. + param_length(pos_a) = 5; + // Calculating necessary spacing for name column, // bytes column, elements column and class column @@ -1798,6 +1804,9 @@ Automatic variable. An automatic variable is one created by the\n\ interpreter, for example @code{argn}.\n\ \n\ address@hidden @code{c}\n\ +Variable of complex type.\n\ +\n\ @item @code{f}\n\ Formal parameter (function argument).\n\ \n\ changeset: 12638:fd367312095a parent: 12635:83fa84ef63ca user: Daniel Kraft date: Tue Apr 05 11:15:50 2011 +0200 files: src/oct-parse.yy description: oct-parse.yy (skip_white_space): Fix column number calculation. diff -r 83fa84ef63ca -r fd367312095a src/oct-parse.yy --- a/src/oct-parse.yy Mon Apr 25 12:32:22 2011 -0700 +++ b/src/oct-parse.yy Tue Apr 05 11:15:50 2011 +0200 @@ -3340,11 +3340,10 @@ break; case '\n': - current_input_column = 0; + current_input_column = 1; break; default: - current_input_column--; reader.ungetc (c); goto done; }