Added functionality for profiling of code executed on the native backend SequentialInterpreter.

Native profiling involves several components:
- C++ NativeProfiler class in execution.cpp, which plays the role
  of compilation._Profiler
- Calls to update the profiler from SequentialInterpreter.run
- Python wrapper for NativeProfiler in cycgt.pyx (NativeProfilerWrapper)
- A reference to the wrapper is stored as a variable in the cycgt module
  (native_profiler)
- In order for us to be consistent in displaying the profiling output on
  a per-Op (rather than per-instruction) basis, we need a way to map each
  C++ Instruction instance back to the Python Instr instance from which it
  derives.  In order to make this possible I added a call in
  CppInterpreterWrapper__init__ that tells the NativeProfilerWrapper to
  store the mappings.
- A C++ Instruction cannot (easily/safely) refer back to the Python
  op, but we need the op description to properly display the profile
  results; therefore I have passed the op description as a string
  op_repr which is stored in the Instruction class and passed back to
  Python for display when

From a user perspective the profiling interface should remain unchanged,
i.e. cgt.profile.start, cgt.profile.print_stats... etc, should work as
before but the results will now include native operations.  But note
that cgt.profiler.instr2stats will NOT include native calls.

TODO:
- Make this work for ParallelInterpreter.
- Since the Instruction->Instr mapping may be useful outside of profiling
  I feel it may be better to refactor and store this information somewhere
  else.

Author: RichardWarfield

cgt/compilation.py

@@ -819,34 +819,51 @@ def __init__(self):
         self.instr2stats = {}
         self.on = False
         self.t_total = 0.0
-    def start(self): self.on = True
-    def stop(self): self.on = False
+    def start(self):
+        self.on = True
+        if not python_only():
+            cgt.cycgt.native_profiler.start()
+    def stop(self):
+        self.on = False
+        if not python_only():
+            cgt.cycgt.native_profiler.stop()
     def update(self, instr, elapsed):
+        # For native code, update happens in C++, not here
         (prevcount, prevtime) = self.instr2stats.get(instr, (0,0.0))
         self.instr2stats[instr] = (prevcount+1, prevtime+elapsed)
         self.t_total += elapsed
     def print_stats(self):
         op2stats = {}
         # Collapse by Op, rather than instruction
-        for (instr,(count,t)) in self.instr2stats.iteritems():
-            if isinstance(instr, (ReturnByRef, ReturnByVal)):
-                opkey = str(instr.op)
-            elif isinstance(instr, Alloc):
-                opkey = "Alloc{dtype=%s,ndim=%i}"%(instr.dtype, len(instr.read_locs))
-            else:
-                opkey = instr.__class__.__name__
+        statdicts = [ self.instr2stats ]
+        if not python_only(): statdicts += [cgt.cycgt.native_profiler.get_instr2stats()]
+        for i2s in statdicts:
+            for (instr,(count,t)) in i2s.iteritems():
+                if isinstance(instr, (ReturnByRef, ReturnByVal)):
+                    opkey = str(instr.op)
+                elif isinstance(instr, Alloc):
+                    opkey = "Alloc{dtype=%s,ndim=%i}"%(instr.dtype, len(instr.read_locs))
+                else:
+                    opkey = instr.__class__.__name__
 
-            (prevcount, prevtime) = op2stats.get(opkey, (0, 0.0))
-            op2stats[opkey] = (prevcount+count, prevtime+t)
+                (prevcount, prevtime) = op2stats.get(opkey, (0, 0.0))
+                op2stats[opkey] = (prevcount+count, prevtime+t)
+
+        if python_only():
+            t_grand_total = self.t_total
+        else:
+            t_grand_total = self.t_total + cgt.cycgt.native_profiler.get_t_total()
+        print "Total time elapsed: %.3g seconds"%t_grand_total
 
-        print "Total time elapsed: %.3g seconds"%self.t_total
         # _print_heading("By instruction")
         # _print_stats(self.instr2stats, self.t_total)
         _print_heading("By Op")
-        _print_stats(op2stats, self.t_total)
+        _print_stats(op2stats, t_grand_total)
     def clear_stats(self):
         self.instr2stats = {}
         self.t_total = 0.0
+        if not python_only() and cgt.cycgt.native_profiler is not None:
+            cgt.cycgt.native_profiler.clear_stats()
 
 profiler = _Profiler()
 

examples/demo_mnist.py

@@ -76,6 +76,7 @@ def main():
     parser.add_argument("--unittest",action="store_true")
     parser.add_argument("--grad_check",action="store_true")
     parser.add_argument("--devtype",choices=["cpu","gpu"],default="cpu")
+    parser.add_argument("--backend",choices=["native","python"],default="native")
     args = parser.parse_args()
 
     if args.grad_check: cgt.set_precision("quad")
@@ -89,7 +90,7 @@ def main():
 
     np.random.seed(0)
 
-    cgt.update_config(default_device=cgt.core.Device(devtype=args.devtype), backend="native")
+    cgt.update_config(default_device=cgt.core.Device(devtype=args.devtype), backend=args.backend)
 
     if args.model=="conv":
         Xdata = Xdata.reshape(-1, 1, 28, 28)
@@ -163,7 +164,7 @@ def main():
         trainerr, trainloss = computeloss(Xtrain[:len(Xtest)], ytrain[:len(Xtest)])
         testerr, testloss = computeloss(Xtest, ytest)
         print fmt_row(10, [i_epoch, trainloss, trainerr, testloss, testerr, elapsed])
-    if args.profile: cgt.execution.profiler.print_stats()
+    if args.profile: cgt.profiler.print_stats()
 
 if __name__ == "__main__":
-    main()
+    main()

include/execution.h

@@ -1,11 +1,18 @@
 #pragma once
 #include "cgt_common.h"
 #include <vector>
+#include <memory>
+#include <map>
 #include <thread>
 #include <string>
+#include <chrono>
 
 namespace cgt {
 using std::vector;
+using std::map;
+using std::unique_ptr;
+
+typedef std::chrono::high_resolution_clock Clock;
 
 // note: no-args initializers are only here because they're required by cython
 
@@ -54,17 +61,19 @@ enum InstructionKind {
 
 class Instruction {
 public:
-    Instruction(InstructionKind kind, const std::string& repr, bool quick) : kind_(kind), repr_(repr), quick_(quick) { }
+    Instruction(InstructionKind kind, const std::string& repr, long pyinstr_hash, bool quick) : kind_(kind), repr_(repr), pyinstr_hash_(pyinstr_hash), quick_(quick) {  }
     virtual void fire(Interpreter*)=0;
     virtual ~Instruction() {};
     virtual const vector<MemLocation>& get_readlocs() const=0;
     virtual const MemLocation& get_writeloc() const=0;
     const std::string& repr() const { return repr_; }
+    const long pyinstr_hash() const { return pyinstr_hash_; }
     const InstructionKind kind() const {return kind_;}
     const bool quick() {return quick_;}
 private:
     InstructionKind kind_;
     std::string repr_;
+    long pyinstr_hash_;
     bool quick_;
 };
 
@@ -99,7 +108,7 @@ Interpreter* create_interpreter(ExecutionGraph*, vector<MemLocation> output_locs
 
 class LoadArgument : public Instruction  {
 public:
-    LoadArgument(const std::string& repr, int ind, const MemLocation& writeloc) : Instruction(LoadArgumentKind, repr, true), ind(ind), writeloc(writeloc) {}
+    LoadArgument(const std::string& repr, const long pyinstr_hash, int ind, const MemLocation& writeloc) : Instruction(LoadArgumentKind, repr, pyinstr_hash, true), ind(ind), writeloc(writeloc) {}
     void fire(Interpreter*);
     const vector<MemLocation>& get_readlocs() const { return readlocs; }
     const MemLocation& get_writeloc() const { return writeloc; }
@@ -112,8 +121,8 @@ class LoadArgument : public Instruction  {
 
 class Alloc : public Instruction {
 public:
-    Alloc(const std::string& repr, cgtDtype dtype, vector<MemLocation> readlocs, const MemLocation& writeloc)
-    : Instruction(AllocKind, repr, true), dtype(dtype), readlocs(readlocs), writeloc(writeloc) {}
+    Alloc(const std::string& repr, const long pyinstr_hash, cgtDtype dtype, vector<MemLocation> readlocs, const MemLocation& writeloc)
+    : Instruction(AllocKind, repr, pyinstr_hash, true), dtype(dtype), readlocs(readlocs), writeloc(writeloc) {}
     void fire(Interpreter*);
     const vector<MemLocation>& get_readlocs() const { return readlocs; }
     const MemLocation& get_writeloc() const { return writeloc; }
@@ -125,8 +134,8 @@ class Alloc : public Instruction {
 
 class BuildTup : public Instruction {
 public:
-    BuildTup(const std::string& repr, vector<MemLocation> readlocs, const MemLocation& writeloc)
-    : Instruction(BuildTupKind, repr, true), readlocs(readlocs), writeloc(writeloc) {}
+    BuildTup(const std::string& repr, const long pyinstr_hash, vector<MemLocation> readlocs, const MemLocation& writeloc)
+    : Instruction(BuildTupKind, repr, pyinstr_hash, true), readlocs(readlocs), writeloc(writeloc) {}
     void fire(Interpreter*);
     const vector<MemLocation>& get_readlocs() const { return readlocs; }
     const MemLocation& get_writeloc() const { return writeloc; }
@@ -137,8 +146,8 @@ class BuildTup : public Instruction {
 
 class ReturnByRef : public Instruction  {
 public:
-    ReturnByRef(const std::string& repr, vector<MemLocation> readlocs, const MemLocation& writeloc, ByRefCallable callable, bool quick)
-    : Instruction(ReturnByRefKind, repr, quick), readlocs(readlocs), writeloc(writeloc), callable(callable) {}
+    ReturnByRef(const std::string& repr, const long pyinstr_hash, vector<MemLocation> readlocs, const MemLocation& writeloc, ByRefCallable callable, bool quick)
+    : Instruction(ReturnByRefKind, repr, pyinstr_hash, quick), readlocs(readlocs), writeloc(writeloc), callable(callable) {}
     void fire(Interpreter*);
     const vector<MemLocation>& get_readlocs() const { return readlocs; }
     const MemLocation& get_writeloc() const { return writeloc; }
@@ -150,8 +159,8 @@ class ReturnByRef : public Instruction  {
 
 class ReturnByVal : public Instruction  {
 public:
-    ReturnByVal(const std::string& repr, vector<MemLocation> readlocs, const MemLocation& writeloc, ByValCallable callable, bool quick)
-    : Instruction(ReturnByValKind, repr, quick), readlocs(readlocs), writeloc(writeloc), callable(callable) {}
+    ReturnByVal(const std::string& repr, const long pyinstr_hash, vector<MemLocation> readlocs, const MemLocation& writeloc, ByValCallable callable, bool quick)
+    : Instruction(ReturnByValKind, repr, pyinstr_hash, quick), readlocs(readlocs), writeloc(writeloc), callable(callable) {}
     void fire(Interpreter*);
     const vector<MemLocation>& get_readlocs() const { return readlocs; }
     const MemLocation& get_writeloc() const { return writeloc; }
@@ -161,5 +170,60 @@ class ReturnByVal : public Instruction  {
     ByValCallable callable;
 };
 
+class InstructionStats {
+public:
+    std::string instr_repr;
+    long pyinstr_hash;
+    int count;
+    double time_total;
+    InstructionStats(std::string instr_repr, long pyinstr_hash, int count, double time_total) {
+        this->instr_repr = instr_repr; this->pyinstr_hash = pyinstr_hash; this->count = count; this->time_total=time_total;
+    }
+};
+
+class NativeProfiler {
+public:
+
+    void start() { on = true; } ;
+    void stop() { on = false; } ;
+    bool is_on() { return on; } ;
+    void update(Instruction* instr, double elapsed) {
+        if (instr2stats.count(instr) == 0) {
+            instr2stats[instr] = new InstructionStats(instr->repr(), instr->pyinstr_hash(), 1, elapsed);
+        } else {
+            instr2stats[instr]->count += 1;
+            instr2stats[instr]->time_total += elapsed;
+        }
+        t_total += elapsed;
+    }
+    void clear_stats() {
+        instr2stats.clear();
+        t_total = 0.0;
+    }
+    double get_t_total() {
+        return t_total;
+    }
+
+    void print_stats();
+
+    vector<InstructionStats*> *get_instr_stats() {
+        vector<InstructionStats*> *result = new vector<InstructionStats*>();
+        map<Instruction*, InstructionStats*>::iterator iter = instr2stats.begin();
+        
+        for(; iter != instr2stats.end(); iter++) {
+            result->push_back(iter->second);
+        }
+        return result;
+    }
+
+    static NativeProfiler* get_profiler() { return &native_profiler;}
+
+
+private:
+    bool on;
+    double t_total;
+    map<Instruction*, InstructionStats*> instr2stats;
+    static NativeProfiler native_profiler;
+};
 
 }

src/cycgt.pyx

@@ -247,21 +247,39 @@ cdef extern from "execution.h" namespace "cgt":
         ExecutionGraph(vector[Instruction*], int, int)        
         int n_args()
     cppclass LoadArgument(Instruction):
-        LoadArgument(const string&, int, const MemLocation&)
+        LoadArgument(const string&, int, int, const MemLocation&)
     cppclass Alloc(Instruction):
-        Alloc(const string&, cgtDtype, vector[MemLocation], const MemLocation&)
+        Alloc(const string&, int, cgtDtype, vector[MemLocation], const MemLocation&)
     cppclass BuildTup(Instruction):
-        BuildTup(const string&, vector[MemLocation], const MemLocation&)
+        BuildTup(const string&, int, vector[MemLocation], const MemLocation&)
     cppclass ReturnByRef(Instruction):
-        ReturnByRef(const string&, vector[MemLocation], const MemLocation&, ByRefCallable, bint)
+        ReturnByRef(const string&, int, vector[MemLocation], const MemLocation&, ByRefCallable, bint)
     cppclass ReturnByVal(Instruction):
-        ReturnByVal(const string&, vector[MemLocation], const MemLocation&, ByValCallable, bint)
+        ReturnByVal(const string&, int, vector[MemLocation], const MemLocation&, ByValCallable, bint)
 
     cppclass Interpreter:
         cgtTuple* run(cgtTuple*)
 
+    cppclass NativeProfiler:
+        void start()
+        void stop()
+        void update(Instruction, double)
+        void print_stats()
+        void clear_stats()
+        double get_t_total() 
+        vector[InstructionStats*] *get_instr_stats();
+        @staticmethod
+        NativeProfiler* get_profiler()
+    
+    struct InstructionStats:
+        string instr_repr
+        long pyinstr_hash
+        int count
+        double time_total
+
     Interpreter* create_interpreter(ExecutionGraph*, vector[MemLocation], int)
 
+
 cdef vector[size_t] _tovectorlong(object xs):
     cdef vector[size_t] out = vector[size_t]()
     for x in xs: out.push_back(<size_t>x)
@@ -346,15 +364,15 @@ cdef Instruction* _tocppinstr(object pyinstr, object storage) except *:
     cdef Instruction* out
     cdef MemLocation wloc = _tocppmem(pyinstr.write_loc)
     if t == compilation.LoadArgument:
-        out = new LoadArgument(repr(pyinstr), pyinstr.ind, wloc)
+        out = new LoadArgument(repr(pyinstr), hash(pyinstr), pyinstr.ind, wloc)
     elif t == compilation.Alloc:
-        out = new Alloc(repr(pyinstr), dtype_fromstr(pyinstr.dtype), _tocppmemvec(pyinstr.read_locs), wloc)
+        out = new Alloc(repr(pyinstr), hash(pyinstr), dtype_fromstr(pyinstr.dtype), _tocppmemvec(pyinstr.read_locs), wloc)
     elif t == compilation.BuildTup:
-        out = new BuildTup(repr(pyinstr), _tocppmemvec(pyinstr.read_locs), wloc)
+        out = new BuildTup(repr(pyinstr), hash(pyinstr), _tocppmemvec(pyinstr.read_locs), wloc)
     elif t == compilation.ReturnByRef:
-        out = new ReturnByRef(repr(pyinstr), _tocppmemvec(pyinstr.read_locs), wloc, _tocppbyrefcallable(pyinstr.get_callable(), storage), _isquick(pyinstr))
+        out = new ReturnByRef(repr(pyinstr), hash(pyinstr), _tocppmemvec(pyinstr.read_locs), wloc, _tocppbyrefcallable(pyinstr.get_callable(), storage), _isquick(pyinstr))
     elif t == compilation.ReturnByVal:
-        out = new ReturnByVal(repr(pyinstr), _tocppmemvec(pyinstr.read_locs), wloc, _tocppbyvalcallable(pyinstr.get_callable(), storage), _isquick(pyinstr))
+        out = new ReturnByVal(repr(pyinstr), hash(pyinstr), _tocppmemvec(pyinstr.read_locs), wloc, _tocppbyvalcallable(pyinstr.get_callable(), storage), _isquick(pyinstr))
     else:
         raise RuntimeError("expected instance of type Instruction. got type %s"%t)
     return out
@@ -420,6 +438,7 @@ cdef class CppInterpreterWrapper:
     def __init__(self, pyeg, input_types, output_locs, parallel):
         self.storage = []
         self.eg = make_cpp_execution_graph(pyeg, self.storage)
+        native_profiler.save_instructions(pyeg)
         cdef vector[MemLocation] cpp_output_locs = _tocppmemvec(output_locs)
         self.interp = create_interpreter(self.eg, cpp_output_locs, parallel)
         self.input_types = input_types
@@ -439,6 +458,46 @@ cdef class CppInterpreterWrapper:
         del cargs
         return list(cgt2py_object(ret.get(), False)) # TODO maybe allow returning view?
 
+cdef class NativeProfilerWrapper:
+    cdef NativeProfiler* _profiler
+    cdef public object _py_instr_map
+    def __cinit__(self):
+        self._profiler = NativeProfiler.get_profiler()
+    def __init__(self):
+        # Maps hash values back to the instruction they hashed
+        self._py_instr_map = {}
+    def save_instructions(self, pyeg):
+        """ 
+        Updates self._py_instr_map with mappings hash(instr) -> instr so that we can find the
+        python instruction from the hash value stored in the C++ Instruction
+        """
+        for instr in pyeg.instrs:
+            self._py_instr_map[hash(instr)] = instr
+    def start(self):
+        self._profiler.start()
+    def stop(self):
+        self._profiler.stop()
+    def get_t_total(self):
+        return self._profiler.get_t_total()
+    def print_stats(self):
+        self._profiler.print_stats()
+    def clear_stats(self):
+        self._profiler.clear_stats()
+    def get_instr2stats(self):
+        cdef vector[InstructionStats*] *istats_vec = self._profiler.get_instr_stats()
+        instr2stats = {}
+        for istats in istats_vec[0]:
+            try:
+                pyinstr = self._py_instr_map[istats[0].pyinstr_hash] 
+            except KeyError:
+                print "Warning, instruction with hash not recorded by profiler" , istats[0].pyinstr_hash
+                continue
+            instr2stats[pyinstr] = (istats[0].count, istats[0].time_total)
+        return instr2stats
+
+native_profiler = NativeProfilerWrapper()
+
+
 def cgt_build_root():
     return osp.dirname(osp.dirname(osp.abspath(__file__)))
 
@@ -456,4 +515,4 @@ def apply_byref(fptr, cldata, inputs, output):
 
     # for (i,x) in enumerate(inputs): reads[i] = 
     # <cgtByRefFun>_getfuncptr(fptr), _getstructptr(cldata), [py2cgt_object(x) for x in inputs]
-    # del[] reads
+    # del[] reads