timing information added in debugprint

On Tue, Dec 2, 2014 at 9:53 AM, vdumoulin <notifications@github.com> wrote:

> In theano/compile/debugmode.py:
>
> >          else:
> > -            print >> file, '%s%s.%i %s%s \'%s\' %s %s %s' % (prefix, a.op,
> > -                                                             a.outputs.index(r),
> > -                                                             id_str, type_str,
> > -                                                             r_name,
> > -                                                             destroy_map_str,
> > -                                                             view_map_str,
> > -                                                             o)
> > +            op_time = profile.apply_time[a]
> > +            op_time_percent = (op_time / profile.fct_call_time) * 100
> > +            tot_time_dict = profile.compute_total_times()
> > +            tot_time = tot_time_dict[a]
> > +            tot_time_percent = (tot_time / max(tot_time_dict.values())) * 100
>
> I had a discussion offline with @nouiz <https://github.com/nouiz> .
> You're absolutely right, this number may go over 100% (e.g. for a node near
> the output node whose inputs share common ancestors), but this is something
> we're okay with as long as it's clearly indicated.
>
> It's there mostly to help rule out nodes when examining the graph for
> optimizations: if this number is low for a node, it means that even in the
> absolute worst case we would not gain very much by removing that node from
> the graph.
>
> We should rework the legend that's printed before a debugprint to make it
> look like
>
> Timing Info
> -----------
> --> <time> <% time> - <total time> <% total time>'
>
>     <time>         computation time for this node
>     <% time>       fraction of total computation time for this node
>     <total time>   time for this node + total times for this node's inputs
>
>
node's inputs -> node's ancestors.  (not just direct inputs)

>
>     <% total time> total time for this node over total computation time
>
> for this node -> for this node and ancestors


>
>
> N.B.: <total time> and <% total time> may over-count computation times
> if inputs to a node share a common ancestor and should be viewed as a
> loose upper bound. Their intended use is to help rule out potential nodes
> to remove when optimizing a graph because their <total time> is very low.
>
>