added the cumulatif of % column into the profile mode and made the column a…

theano/compile/profilemode.py

@@ -191,17 +191,18 @@ class ProfileMode(Mode):
         print 'local_time %.3fs (Time spent running thunks)'% local_time
 
         if print_apply:
-            print 'Apply-wise summary: <% of local_time spent at this position> <cumulative seconds> <apply time> <time per call> <nb_call> <Apply position> <Apply Op name>'
-            atimes = [(t/local_time, t, (a[0], str(a[1])), apply_call[a]) for a, t in apply_time.items()]
+            print 'Apply-wise summary: <% of local_time spent at this position> <cumulative %%> <apply time> <cumulative seconds> <time per call> <nb_call> <Apply position> <Apply Op name>'
+            atimes = [(t*100/local_time, t, (a[0], str(a[1])), apply_call[a]) for a, t in apply_time.items()]
             atimes.sort()
             atimes.reverse()
             tot=0
             for f,t,a,nb_call in atimes[:n_apply_to_print]:
                 tot+=t
-                print '   %4.1f%%  %.3fs  %.3fs %.2es  %i  %i %s' % (f*100, tot, t, t/nb_call,nb_call, a[0], a[1])
+                ftot=tot*100/local_time
+                print '   %4.1f%%  %5.1f%%  %5.3fs  %5.3fs %.2es  %i  %i %s' % (f, ftot, t, tot, t/nb_call,nb_call, a[0], a[1])
             print '   ... (remaining %i Apply instances account for %.2f%%(%.2fs) of the runtime)'\
                     %(max(0, len(atimes)-n_apply_to_print),
-                      sum(f for f, t, a, nb_call in atimes[n_apply_to_print:])*100,
+                      sum(f for f, t, a, nb_call in atimes[n_apply_to_print:]),
                       sum(t for f, t, a, nb_call in atimes[n_apply_to_print:]))
 
         op_time = {}
@@ -224,9 +225,9 @@ class ProfileMode(Mode):
         if op_flops:
             flops_msg=' <MFlops/s>'
             print '\nHACK WARNING: we print the flops for some OP, but the logic don\' always work. You need to know the internal of Theano to make it work correctly. Otherwise don\'t use!'
-        print '\nOp-wise summary: <%% of local_time spent on this kind of Op> <cumulative seconds> <self seconds> <time per call> %s <nb_call> <nb apply> <Op name>'%(flops_msg)
+        print '\nOp-wise summary: <%% of local_time spent on this kind of Op> <cumulative %%> <self seconds> <cumulative seconds> <time per call> %s <nb_call> <nb apply> <Op name>'%(flops_msg)
 
-        otimes = [(t/local_time, t, a, op_cimpl.get(a, 0), op_call.get(a, 0), op_apply.get(a,0)) 
+        otimes = [(t*100/local_time, t, a, op_cimpl.get(a, 0), op_call.get(a, 0), op_apply.get(a,0)) 
                 for a, t in op_time.items()]
         otimes.sort()
         otimes.reverse()
@@ -236,17 +237,18 @@ class ProfileMode(Mode):
                 assert t == 0
                 continue
             tot+=t
+            ftot=tot*100/local_time
             if ci:
               msg = '*'
             else:
               msg = ' '
             if op_flops:
-                print '   %4.1f%%  %.3fs  %.3fs  %.2es %s %7.1f %d %d %s' % (f*100, tot, t, t/nb_call, msg, op_flops.get(a,-1), nb_call, nb_apply, a)
+                print '   %4.1f%%  %5.1f%%  %5.3fs  %5.3fs  %.2es %s %7.1f %5d %2d %s' % (f, ftot, t, tot, t/nb_call, msg, op_flops.get(a,-1), nb_call, nb_apply, a)
             else:
-                print '   %4.1f%%  %.3fs  %.3fs  %.2es  %s %d %d %s' % (f*100, tot, t, t/nb_call, msg, nb_call, nb_apply, a)
+                print '   %4.1f%%  %5.1f%%  %5.3fs  %5.3fs  %.2es %s %5d %2d %s' % (f, ftot, t, tot, t/nb_call, msg, nb_call, nb_apply, a)
         print '   ... (remaining %i Ops account for %6.2f%%(%.2fs) of the runtime)'\
                 %(max(0, len(otimes)-n_ops_to_print),
-                  sum(f for f, t, a, ci, nb_call, nb_op in otimes[n_ops_to_print:])*100,
+                  sum(f for f, t, a, ci, nb_call, nb_op in otimes[n_ops_to_print:]),
                   sum(t for f, t, a, ci, nb_call, nb_op in otimes[n_ops_to_print:]))
         print '(*) Op is running a c implementation'
 
@@ -263,8 +265,8 @@ class ProfileMode(Mode):
             sop_c.setdefault(type(a),True)
             sop_c[type(a)]=sop_c[type(a)] and op_cimpl.get(a, False)
             sop_call[type(a)]=sop_call.get(type(a),0)+op_call[a]
-        print '\nSingle Op-wise summary: <% of local_time spent on this kind of Op> <cumulative seconds> <self seconds> <time per call> <nb_call> <nb_op> <nb_op> <Op name>'
-        sotimes = [(t/local_time, t, a, sop_c[a], sop_call[a], sop_op[a]) for a, t in sop_time.items()]
+        print '\nSingle Op-wise summary: <% of local_time spent on this kind of Op> <cumulative %%> <self seconds> <cumulative seconds> <time per call> <nb_call> <nb_op> <nb_op> <Op name>'
+        sotimes = [(t*100/local_time, t, a, sop_c[a], sop_call[a], sop_op[a]) for a, t in sop_time.items()]
         sotimes.sort()
         sotimes.reverse()
         tot=0
@@ -273,14 +275,15 @@ class ProfileMode(Mode):
                 assert t == 0
                 continue
             tot+=t
+            ftot=tot*100/local_time
             if ci:
               msg = '*'
             else:
               msg = ' '
-            print '   %4.1f%%  %.3fs  %.3fs  %.2es %s %d %d %s' % (f*100, tot, t, t/nb_call, msg, nb_call, nb_op, a)
+            print '   %4.1f%%  %5.1f%%  %5.3fs  %5.3fs  %.2es %s %5d %2d %s' % (f, ftot, t, tot, t/nb_call, msg, nb_call, nb_op, a)
         print '   ... (remaining %i Ops account for %.2f%%(%.2fs) of the runtime)'\
                 %(max(0, len(sotimes)-n_ops_to_print),
-                  sum(f for f, t, a, ci, nb_call, nb_op in sotimes[n_ops_to_print:])*100,
+                  sum(f for f, t, a, ci, nb_call, nb_op in sotimes[n_ops_to_print:]),
                   sum(t for f, t, a, ci, nb_call, nb_op in sotimes[n_ops_to_print:]))
 
         print '(*) Op is running a c implementation'