Profiling Duplication
=========================

TODO
------

OpticksProfile uses Timer internally, but other bare usage remains.

* move persisted OpticksProfile contents into a folder named OpticksProfile at top level
  and duplicate that within datestamped folders, following the old pattern of Timer

* get rid of legacy direct usage of npy/Timer


OpticksProfile
----------------

Canonical m_profile instance resides in Opticks instance, and is created with it.
Used from Opticks via OK_PROFILE::

     39 #define OK_PROFILE(s) \
     40     { \
     41        if(m_ok)\
     42        {\
     43           m_ok->profile((s)) ;\
     44        }\
     45     }

     215 template <typename T>
     216 void Opticks::profile(T label)
     221 void Opticks::dumpProfile(const char* msg, const char* startswith, const char* spacewith, double tcut)
     225 void Opticks::saveProfile()

::

     217 template <typename T>
     218 void Opticks::profile(T label)
     219 {
     220     m_profile->stamp<T>(label, m_tagoffset);
     221    // m_tagoffset is set by Opticks::makeEvent
     222 }





    simon:opticks blyth$ opticks-find OK_PROFILE | wc -l
          38

Profile stamps are persisted in ini and npy, holding the same information::

    /tmp/blyth/opticks/evt/boolean/torch
    simon:torch blyth$ l
    total 40
    drwxr-xr-x  12 blyth  wheel  408 Mar  4 14:09 -1
    drwxr-xr-x  23 blyth  wheel  782 Mar  4 14:09 1
    -rw-r--r--   1 blyth  wheel  701 Mar  4 14:09 DeltaTime.ini
    -rw-r--r--   1 blyth  wheel  573 Mar  4 14:09 DeltaVM.ini
    -rw-r--r--   1 blyth  wheel  480 Mar  4 14:09 Opticks.npy
    -rw-r--r--   1 blyth  wheel  776 Mar  4 14:09 Time.ini
    -rw-r--r--   1 blyth  wheel  656 Mar  4 14:09 VM.ini

Looks like this is currently only done at top level, not 
in the date stamped folders. So only the last invokation times
are available.


Related : npy-/Timer
-------------------------


Other time info is stored with the saved events in t_delta.ini and t_absolute.ini::

    simon:torch blyth$ cat 1/20170304_140910/t_delta.ini 
    _seqhisMakeLookup=0.72714199999973061
    seqhisMakeLookup=0.010654000001522945
    seqhisApplyLookup=2.0999999833293259e-05
    _seqmatMakeLookup=9.9999670055694878e-07
    seqmatMakeLookup=0.006623000001127366
    seqmatApplyLookup=1.5000001440057531e-05
    indexSequenceInterop=0.03241399999751593
    indexBoundaries=0.034935000003315508
    _save=0.11633399999846006
    save=0.15342500000042492

These are default column names from::

    opticksnpy/Timer.cpp

Canonical Timer instance::

    m_timer = new Timer("Opticks::");   


::

    simon:opticks blyth$ opticks-find m_timer
    ./optickscore/Opticks.cc:       m_timer(NULL),
    ./optickscore/Opticks.cc:    m_timer = new Timer("Opticks::");
    ./optickscore/Opticks.cc:    m_timer->setVerbose(true);
    ./optickscore/Opticks.cc:    m_timer->start();
    ./optickscore/Opticks.cc:    return m_timer ; 
    ./optickscore/OpticksEvent.cc:       if(m_timer)\
    ./optickscore/OpticksEvent.cc:          Timer& t = *(m_timer) ;\
    ./optickscore/OpticksEvent.cc:          m_timer(NULL),
    ./optickscore/OpticksEvent.cc:    return m_timer ;
    ./optickscore/OpticksEvent.cc:    m_timer = new Timer("OpticksEvent"); 
    ./optickscore/OpticksEvent.cc:    m_timer->setVerbose(false);
    ./optickscore/OpticksEvent.cc:    m_timer->start();
    ./optickscore/OpticksEvent.cc:    (*m_timer)("_save");
    ./optickscore/OpticksEvent.cc:    (*m_timer)("save");
    ./optickscore/OpticksEvent.cc:    m_timer->stop();
    ./optickscore/OpticksEvent.cc:    m_ttable = m_timer->makeTable();
    ./optickscore/OpticksEvent.cc:    (*m_timer)("load");
    ./optixrap/OScene.cc:       (*m_timer)((s)); \
    ./optixrap/OScene.cc:      m_timer(new Timer("OScene::")),
    ./optixrap/OScene.cc:    m_timer->setVerbose(true);
    ./optixrap/OScene.cc:    m_timer->start();
    ./optickscore/Opticks.hh:       Timer*               m_timer ; 
    ./optickscore/OpticksEvent.hh:       Timer*                m_timer ;
    ./optickscore/OpticksProfile.hh:    m_timer = new Timer("Opticks::");   
    ./optixrap/OScene.hh:       Timer*               m_timer ;
    simon:opticks blyth$ 

::

    1563 void OpticksEvent::makeReport(bool verbose)
    1564 {
    1565     LOG(info) << "OpticksEvent::makeReport " << getTagDir()  ;
    1566 
    1567     if(verbose)
    1568     m_parameters->dump();
    1569 
    1570     m_timer->stop();
    1571 
    1572     m_ttable = m_timer->makeTable();
    1573     if(verbose)
    1574     m_ttable->dump("OpticksEvent::makeReport");
    1575 
    1576     m_report->add(m_parameters->getLines());
    1577     m_report->add(m_ttable->getLines());
    1578 }
    1579 
    1580 
    1581 void OpticksEvent::saveReport()
    1582 {
    1583     std::string tagdir = getTagDir();
    1584     saveReport(tagdir.c_str());
    1585 
    1586     std::string anno = getTimeStamp() ;
    1587     std::string tagdir_ts = getTagDir(anno.c_str());
    1588     saveReport(tagdir_ts.c_str());
    1589 }