eic-opticks/ana/profile_.py

0001 #!/usr/bin/env python
0002 #
0003 # Copyright (c) 2019 Opticks Team. All Rights Reserved.
0004 #
0005 # This file is part of Opticks
0006 # (see https://bitbucket.org/simoncblyth/opticks).
0007 #
0008 # Licensed under the Apache License, Version 2.0 (the "License");
0009 # you may not use this file except in compliance with the License.
0010 # You may obtain a copy of the License at
0011 #
0012 #   http://www.apache.org/licenses/LICENSE-2.0
0013 #
0014 # Unless required by applicable law or agreed to in writing, software
0015 # distributed under the License is distributed on an "AS IS" BASIS,
0016 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
0017 # See the License for the specific language governing permissions and
0018 # limitations under the License.
0019 #
0020
0021 """
0022 profile_.py
0023 =============
0024
0025 Renamed from profile.py due to notes/issues/ipython-ipdb-issue.rst
0026
0027 ::
0028
0029     TEST=OpticksRunTest ipython -i ~/opticks/ana/profile_.py -- --tag 0
0030
0031
0032     LV=box profile_.py
0033     LV=box python2.7 profile_.py
0034
0035
0036     LV=box ipython -i profile_.py
0037
0038     LV=0 ip profile_.py
0039
0040     LV=box ip profile_.py --cat cvd_1_rtx_1_1M --pfx scan-ph --tag 0
0041
0042     ip(){ local arg1=${1:-evt.py}; shift; ipython -i -- $(which $arg1) $* ; }
0043
0044
0045     ip profile_.py --cat cvd_1_rtx_0_1M --pfx scan-pf-0 --tag 0
0046          OKG4Test run
0047
0048
0049 scan-pf-0 OKG4Test 239s for 1M::
0050
0051     In [17]: ap.times("CRunAction::BeginOfRunAction")
0052     Out[17]: array([1206.6406, 1464.2812, 1708.2578, 1950.6406, 2191.8984, 2439.336 , 2681.1562, 2916.8828, 3153.2656, 3389.5   ], dtype=float32)
0053
0054     In [18]: ap.times("CRunAction::EndOfRunAction")
0055     Out[18]: array([1460.2266, 1706.0625, 1948.4453, 2189.6719, 2436.9219, 2678.9219, 2914.6875, 3151.0625, 3387.3281, 3622.4453], dtype=float32)
0056
0057     In [19]: ap.times("CRunAction::EndOfRunAction") - ap.times("CRunAction::BeginOfRunAction")
0058     Out[19]: array([253.5859, 241.7812, 240.1875, 239.0312, 245.0234, 239.5859, 233.5312, 234.1797, 234.0625, 232.9453], dtype=float32)
0059
0060     In [25]: np.average( ap.times("CRunAction::EndOfRunAction") - ap.times("CRunAction::BeginOfRunAction") )
0061     Out[25]: 239.3914
0062
0063
0064     In [22]: ap.times("OPropagator::launch")
0065     Out[22]: array([1463.7578, 1707.7422, 1950.1172, 2191.3594, 2438.7422, 2680.625 , 2916.3516, 3152.7344, 3388.9844, 3624.125 ], dtype=float32)
0066
0067     In [24]: ap.times("OPropagator::launch") - ap.times("_OPropagator::launch")
0068     Out[24]: array([0.6875, 0.6953, 0.6875, 0.6953, 0.8125, 0.7188, 0.6953, 0.6953, 0.6953, 0.6875], dtype=float32)
0069
0070
0071 ::
0072
0073     ip profile_.py --cat cvd_1_rtx_1_1M --pfx scan-pf-0 --tag 0
0074
0075
0076     In [2]: pr.q
0077     Out[2]: array([0.0204, 0.0182, 0.0208, 0.0191, 0.0179, 0.02  , 0.0193, 0.018 , 0.0178, 0.0196])
0078
0079     In [1]: pr.q
0080     Out[1]: array([0.0214, 0.0189, 0.019 , 0.0186, 0.0187, 0.0206, 0.0183, 0.0183, 0.0191, 0.0188])
0081
0082
0083 """
0084
0085 from __future__ import print_function
0086 import os, sys, logging, numpy as np
0087 log = logging.getLogger(__name__)
0088 lmap = lambda *args:list(map(*args))
0089
0090
0091 #from opticks.ana.debug import MyPdb
0092 """
0093 # not working with py3
0094 try:
0095     from IPython.core.debugger import Pdb as MyPdb
0096 except ImportError:
0097     class MyPdb(object):
0098         def set_trace(self):
0099             log.error("IPython is required for ipdb.set_trace() " )
0100         pass
0101     pass
0102 pass
0103 ipdb = MyPdb()
0104 """
0105 ipdb = None
0106
0107 from opticks.ana.log import bold_, blink_
0108 from opticks.ana.base import json_load_
0109 from opticks.ana.base import u_,b_,d_
0110 from opticks.ana.nload import np_load
0111 from opticks.ana.nload import tagdir_, stmp_, time_, tfmt_
0112
0113
0114 def fmtarray_(a):
0115     if a is None:
0116         return "-"
0117     pass
0118     return " ".join(map(lambda v:"%8.4f" % v, a))
0119
0120 class Profile(object):
0121     """
0122     Opticks executables can record time and virtual memory
0123     and codepoint strings at various points throughout operations.
0124     These are recorded into NPY files  such as OpticksProfile.npy
0125     which this Profile class loads.
0126     """
0127     NAME = "OpticksProfile.npy"
0128     G4DT = ("CRunAction::BeginOfRunAction","CRunAction::EndOfRunAction",)
0129     OKDT = ("_OPropagator::launch", "OPropagator::launch",)
0130     PARM = "parameters.json"
0131
0132     def __init__(self, pdir, name, g4=False ):
0133         """
0134         :param pdir: directory from which to load OpticksProfile.npy and siblings,
0135
0136              This was formerly tagdir with expected to be the tag integer string,
0137              negative for G4 ... hmm but its now one up at the torch dir ?
0138
0139         :param name: informational name for outputs
0140         """
0141         self.pdir = pdir
0142         self.name = name
0143         self.g4 = g4
0144
0145         self.sli = slice(0,0)  # nowt
0146         self.fmt = "%Y%m%d-%H%M"
0147
0148         if os.path.exists(self.pdir):
0149             self.init()
0150             self.initLaunch()
0151         else:
0152             self.prfmt = "INVALID"
0153             self.acfmt = "INVALID"
0154             log.fatal("pdir %s DOES NOT EXIST " % self.pdir)
0155         pass
0156
0157     def _get_valid(self):
0158         return hasattr(self, 'tim')
0159     valid = property(_get_valid)
0160
0161
0162     def init(self):
0163         log.debug("[")
0164         self.missing = False  # optimistic start, may be flipped on attempting to load
0165
0166         self.loadProfile()
0167         self.loadAcc()    ## Accumulated timings
0168         self.loadMeta()
0169
0170         if len(self) > 0:
0171             self.initTime()
0172         else:
0173             self.tim = -1
0174             log.debug("didnt load any entries")
0175         pass
0176         log.debug("]")
0177
0178     def initTime(self):
0179         if self.g4:
0180             g4r, g40, g41 = self.deltaT(*self.G4DT)   ## CG4::propagate includes significant initialization
0181             stt = self.setupTrancheTime()
0182             tim = g4r - stt
0183             idx = [g40, g41]
0184         else:
0185             okp, ok0, ok1 = self.deltaT(*self.OKDT)
0186             tim = okp
0187             idx = [ok0, ok1]
0188         pass
0189         self.tim = tim
0190         self.idx = idx
0191         self.sli = slice(idx[0],idx[1]+1)
0192         log.debug("]")
0193
0194     def pfmt(self, path1, path2, path3=None):
0195         """
0196         Check that timestamps of related files are close to each other
0197         """
0198         t_path1 = time_(path1)
0199         t_path2 = time_(path2)
0200         t_path3 = time_(path3) if path3 is not None else None
0201
0202         if t_path1 is None or t_path2 is None:
0203             return "profile_.pfmt missing paths "
0204         pass
0205
0206         flag = 0
0207
0208         if t_path3 is not None:
0209             adt3 = abs(t_path1 - t_path3)
0210             if adt3.seconds > 1:
0211                 flag += 1
0212             pass
0213             #assert adt3.seconds < 1
0214         pass
0215
0216
0217
0218
0219         adt = abs(t_path1 - t_path2)
0220
0221         if adt.seconds > 1:
0222             flag += 1
0223         pass
0224
0225         if flag > 0:
0226             log.warning("pfmt related files timestamps differ by more than 1s 1-3: %10.3f 1-2 %10.3f" % ( adt3.seconds, adt.seconds ))
0227             log.info("path1 %s : %s " % (path1, tfmt_(t_path1)))
0228             log.info("path2 %s : %s " % (path2, tfmt_(t_path2)))
0229             log.info("path3 %s : %s " % (path3, tfmt_(t_path3)))
0230         pass
0231         #assert adt.seconds < 1
0232         return "  %-90s  %s " % ( path1, t_path1.strftime(self.fmt) )
0233
0234     def path(self, sfx=""):
0235         return os.path.join( self.pdir, "OpticksProfile%s.npy" % sfx )   # quads
0236
0237     def metapath(self):
0238         #return os.path.join( self.pdir, "0", self.PARM )
0239         return os.path.join( self.pdir, self.PARM )
0240
0241     def loadMeta(self):
0242         path = self.metapath()
0243         exists = os.path.exists(path)
0244         if not exists:
0245             log.info("path %s does not exist " % path )
0246         pass
0247         meta = json_load_(path) if exists else {}
0248         self.meta = meta
0249         log.debug("loaded %s keys %s " % (path, len(self.meta)))
0250
0251
0252     def loadProfile(self):
0253         """
0254         ::
0255
0256             In [8]: pr.a
0257             Out[8]:
0258             array([[    0.    , 59888.504 ,     0.    ,  4625.252 ],
0259                    [    0.    ,     0.    ,     0.    ,     0.    ],
0260                    [    0.    ,     0.    ,     0.    ,     0.    ],
0261                    [    0.    ,     0.    ,     0.    ,     0.    ],
0262                    [    3.8281,     3.8281,   155.98  ,   155.98  ],
0263                    [    3.8281,     0.    ,   155.98  ,     0.    ],
0264                    [    3.8281,     0.    ,   155.98  ,     0.    ],
0265                    [    3.8281,     0.    ,   156.2988,     0.3188],
0266                    [    3.832 ,     0.0039,   156.8149,     0.5161],
0267
0268             In [10]: pr.l[:10]
0269             Out[10]:
0270             array([b'OpticksRun::OpticksRun', b'Opticks::Opticks', b'_OKG4Mgr::OKG4Mgr', b'_OpticksHub::init', b'_GMergedMesh::Create', b'GMergedMesh::Create::Count', b'_GMergedMesh::Create::Allocate',
0271                    b'GMergedMesh::Create::Allocate', b'GMergedMesh::Create::Merge', b'GMergedMesh::Create::Bounds'], dtype='|S45')
0272
0273         """
0274         log.debug("[")
0275
0276
0277         path = self.path("")
0278         lpath = self.path("Labels")
0279         qpath = self.path("Lis")
0280         self.prfmt = self.pfmt(path, lpath)
0281
0282         if not os.path.exists(path):
0283             log.warning("path %s does not exist " % path)
0284             self.missing = True
0285             return
0286         pass
0287
0288         a = np.load(path)
0289         assert a.ndim == 2
0290         log.debug("path:%s a.shape:%r" % (path,a.shape))
0291
0292         l = np.load(lpath)
0293         assert l.ndim == 2 and l.shape[1] == 64
0294         assert len(a) == len(l)
0295         num = len(a)
0296
0297         log.debug("lpath:%s l.shape:%r" % (lpath,l.shape))
0298
0299         ll = list(l.view("|S64")[:,0])
0300         lll = np.array(ll)
0301
0302         t,dt,v,dv = a[:,0], a[:,1], a[:,2], a[:,3]
0303
0304
0305         q = np.load(qpath) if os.path.exists(qpath) else None
0306         log.debug("qpath:%s q.shape:%r" % (qpath,q.shape))
0307
0308
0309         self.l = lll
0310         self.a = a
0311
0312         self.t = t
0313         self.dt = dt
0314         self.v = v
0315         self.dv = dv
0316
0317         self.q = q
0318
0319
0320         self.apath = path
0321         self.lpath = lpath
0322
0323         log.debug("]")
0324
0325
0326     def __len__(self):
0327         return len(self.a) if self.valid else 0
0328
0329     def loadAcc(self):
0330         """
0331         Acc are accumulated timings
0332         """
0333         log.debug("[")
0334         path = self.path("")
0335         acpath = self.path("Acc")
0336         lacpath = self.path("AccLabels")
0337
0338         self.acfmt = self.pfmt(acpath, lacpath, path)
0339
0340         if not os.path.exists(acpath):
0341             log.warning("path %s does not exist " % acpath )
0342             self.missing = True
0343             return
0344         pass
0345
0346         ac = np.load(acpath)
0347         assert ac.ndim == 2
0348
0349         lac = np.load(lacpath)
0350         assert lac.ndim == 2 and lac.shape[1] == 64
0351         assert len(ac) == len(lac)
0352
0353         self.ac = ac
0354         self.lac = np.array( lac.view("|S64")[:,0] )
0355         log.debug("]")
0356
0357
0358     def acc(self, label):
0359         return self.ac[np.where( self.lac == label )]
0360
0361     def setupTrancheTime(self):
0362         stt_acc = self.acc("CRandomEngine::setupTranche")
0363         assert stt_acc.ndim == 2 and stt_acc.shape[1] == 4
0364         assert len(stt_acc) == 1 or len(stt_acc) == 0
0365         stt = stt_acc[0,1] if len(stt_acc) == 1 else 0.
0366         return stt
0367
0368
0369     def delta_(self, arg0, arg1=None ):
0370         """
0371         :param arg0: start label
0372         :param arg1: end label
0373         :return w0,w1: arrays of indices of matching labels
0374
0375         If arg1 is not provided assume arg0 specifies a pair
0376         using the underscore convention. For example with arg0
0377         as "CG4::propagate" the pair becomes ("_CG4::propagate","CG4::propagate")
0378         """
0379         if arg1 is None:
0380             l0 = "_%s" % arg0
0381             l1 = "%s" % arg0
0382         else:
0383             l0 = arg0
0384             l1 = arg1
0385         pass
0386
0387         w0 = np.where( self.l == b_(l0) )[0]   # array of matching idx, empty if not found
0388         w1 = np.where( self.l == b_(l1) )[0]
0389
0390         return w0, w1
0391
0392     def dv_(self, i0, i1 ):
0393         return self.v[i1]-self.v[i0]
0394
0395     def dt_(self, i0, i1 ):
0396         return self.t[i1]-self.t[i0]
0397
0398
0399     def delta(self, arg0, arg1=None):
0400         """
0401         :param arg0: start label
0402         :param arg1: end label
0403         :return dt, dv:  deltaTime, deltaVM between two OK_PROFILE code points
0404         """
0405         w0, w1 = self.delta_(arg0,arg1 )
0406
0407         i0 = w0[0] if len(w0) == 1 else 0
0408         i1 = w1[0] if len(w1) == 1 else 0
0409
0410         v = self.v
0411         t = self.t
0412
0413         dv = self.dv_(i0,i1)
0414         dt = self.dt_(i0,i1)
0415
0416         log.debug(" i0:%3d i1:%3d  (v0:%10.1f v1:%10.1f dv:%10.1f )  ( t0:%10.4f t1:%10.4f dt:%10.4f )  " % ( i0, i1, self.v[i0],self.v[i1], dv, self.t[i0],self.t[i1], dt  ))
0417         return dt, dv, i0, i1
0418
0419     def times(self, l0="_OPropagator::launch"):
0420         """
0421         :param l0: label of the profile stamp
0422         :return array of all times matching the label:
0423         """
0424         pr = self
0425         if len(pr.l) > 0:
0426             tt = pr.t[np.where(pr.l == b_(l0) )]
0427         else:
0428             tt = np.ndarray(0)   # empty array
0429         pass
0430         return tt
0431
0432     def plt_axvline(self, ax):
0433         """
0434         """
0435         #w0 = np.where( self.l == "_OEvent::uploadSource")[0]
0436         w1, w2 = self.delta_(*self.OKDT)
0437
0438         #assert len(w0) == len(w1)
0439         assert len(w1) == len(w2)
0440
0441         for i in range(len(w1)):
0442             #i0 = w0[i]
0443             i1 = w1[i]
0444             i2 = w2[i]
0445             #ax.axvline( self.t[i0], c="r" )
0446             ax.axvline( self.t[i1], c="g" )
0447             ax.axvline( self.t[i2], c="b" )
0448         pass
0449
0450     def deltaT(self, arg0, arg1=None):
0451         """
0452         :param arg0:
0453         :param arg1:
0454         :return dt,p0,p1: time between labels and indices of the labels
0455         """
0456         dt, dv, p0, p1 = self.delta(arg0, arg1)
0457         return dt, p0, p1
0458
0459     def line(self, i):
0460         li = d_(self.l[i])
0461         if li in self.OKDT:
0462             fn_ = bold_
0463         elif li in self.G4DT:
0464             fn_ = blink_
0465         else:
0466             fn_ = lambda _:_
0467         pass
0468         return " %6d : %50s : %10.4f %10.4f %10.4f %10.4f   " % ( i, fn_(li), self.t[i], self.v[i], self.dt[i], self.dv[i] )
0469
0470     def labels(self):
0471         return " %6s : %50s : %10s %10s %10s %10s   " % ( "idx", "label", "t", "v", "dt", "dv" )
0472
0473
0474     launch_start = property(lambda self:self.times(self.OKDT[0]))
0475     launch_stop = property(lambda self:self.times(self.OKDT[1]))
0476     launch = property(lambda self:self.launch_stop - self.launch_start )
0477
0478     start_interval = property(lambda self:np.diff(self.launch_start))
0479     stop_interval = property(lambda self:np.diff(self.launch_stop))
0480
0481     def initLaunch(self):
0482         """
0483         intervals only defined with "--multievent 2+" running
0484         """
0485         if self.missing:
0486             return
0487         pass
0488
0489         log.debug("[ %r" % self.launch)
0490
0491         if len(self.launch) > 0:
0492             avg_launch = np.average(self.launch)
0493         else:
0494             avg_launch = 0
0495         pass
0496         self.avg_launch = avg_launch
0497         nsta = len(self.start_interval)
0498         nsto = len(self.stop_interval)
0499         assert nsta == nsto
0500         if nsta > 0:
0501             self.multievent = True
0502             self.avg_start_interval = np.average(self.start_interval)
0503             self.avg_stop_interval = np.average(self.stop_interval)
0504             self.overhead_ratio = self.avg_start_interval/self.avg_launch
0505         else:
0506             self.avg_start_interval = -1
0507             self.avg_stop_interval = -1
0508             self.overhead_ratio = -1
0509             self.multievent = False
0510         pass
0511         #ipdb.set_trace()
0512         log.debug("]")
0513
0514     def overheads(self):
0515
0516         print(".launch_start %r ", self.launch_start )
0517         print(".launch_stop  %r ", self.launch_stop  )
0518         print(".launch           avg %10.4f     %r " % (  self.avg_launch         , self.launch  ))
0519
0520         if self.multievent:
0521             print(".start_interval   avg %10.4f     %r " % (  self.avg_start_interval , self.start_interval) )
0522             print(".stop_interval    avg %10.4f     %r " % (  self.avg_stop_interval  , self.stop_interval ) )
0523         pass
0524
0525     def _get_note(self):
0526         return "MULTIEVT" if self.multievent else "not-multi"
0527     note = property(_get_note)
0528
0529
0530     @classmethod
0531     def Labels(cls):
0532         return " %20s %10s %10s %10s %10s : %50s : %50s " % ( "name", "note", "av.interv","av.launch","av.overhd", "launch", "q" )
0533
0534     def brief(self):
0535         return " %20s %10s %10.4f %10.4f %10.4f : %50s : %50s " % (self.name, self.note, self.avg_start_interval, self.avg_launch, self.overhead_ratio, fmtarray_(self.launch), fmtarray_(self.q) )
0536
0537
0538     def bodylines(self):
0539         start = self.sli.start
0540         stop = self.sli.stop
0541         if start is None: start = 0
0542         if stop is None: stop = len(self)
0543
0544         stop = min(len(self), stop)
0545
0546         nli = stop - start
0547         if nli < 10:
0548             ll = lmap(lambda i:self.line(i), np.arange(start, stop))
0549         else:
0550             ll = lmap(lambda i:self.line(i), np.arange(start, start+5) )
0551             ll += [" ..."]
0552             ll += lmap(lambda i:self.line(i), np.arange(stop - 5, stop) )
0553         pass
0554         return ll
0555
0556     def lines(self):
0557         return ["name:",self.name, "prfmt:",self.prfmt, "acfmt:",self.acfmt, "sli:","%r" % self.sli, "labels:",self.labels(),"bodylines:"] + self.bodylines() + ["labels:",self.labels()]
0558
0559     def __str__(self):
0560         return "\n".join(self.lines())
0561
0562     def __repr__(self):
0563         return self.brief()
0564
0565     def __getitem__(self, sli):
0566         self.sli = sli
0567         return self
0568
0569
0570
0571 def multievent_plot( pr, plt ):
0572     """
0573     TODO: split off the plotting
0574
0575     * plotting should never live together with generally usable code, as plotting machinery
0576       has much more dependencies and also prone to being swapped for other plotting machinery
0577     """
0578     w0 = np.where(pr.l == b_("_OpticksRun::createEvent"))[0]
0579     w1 = np.where(pr.l == b_("OpticksRun::resetEvent"))[0]
0580     assert len(w0) == len(w1)
0581
0582     w10 = w1 - w0
0583     uw10 = np.unique(w10[1:])   # exclude the first, as initialization stamps may be different
0584     assert len(uw10) == 1       # number of profile stamps should be the same for all events
0585     uw = uw10[0]
0586
0587     ## each event after the 1st has the same set of labels
0588     for j in range(2, len(w0)): assert np.all( pr.l[w0[1]:w1[1]] == pr.l[w0[j]:w1[j]] )
0589
0590     tt = np.zeros( [9, uw] )
0591     for j in range(1, len(w0)): tt[j-1] = pr.dt[w0[j]:w1[j]]
0592
0593     print("pr[w0[1]:w1[1]]")
0594     print(pr[w0[1]:w1[1]])
0595
0596     fig = plt.figure()
0597     ax = fig.add_subplot(111)
0598
0599
0600     #ax.set_xlim( [pr.t[w0[0]], pr.t[w1[-1]] + 0.5 ])
0601
0602     ax.set_xlim( 4.9, 5.3 )
0603
0604
0605     plt.plot( pr.t, pr.v, 'o' )
0606
0607     pr.plt_axvline(ax)
0608
0609     ax.set_ylabel("Process Virtual Memory (MB)")
0610     ax.set_xlabel("Time since executable start (s)")
0611
0612
0613     plt.ion()
0614     fig.show()
0615
0616
0617 def simple_plot( pr, plt):
0618
0619     fig = plt.figure()
0620     ax = fig.add_subplot(111)
0621
0622     plt.plot( pr.t, pr.v, 'o' )
0623
0624     ax.set_ylabel("Process Virtual Memory (MB)")
0625     ax.set_xlabel("Time since executable start (s)")
0626
0627     plt.ion()
0628     fig.show()
0629
0630
0631
0632
0633
0634 if __name__ == '__main__':
0635     from opticks.ana.main import opticks_main
0636     from opticks.ana.plot import init_rcParams
0637     import matplotlib.pyplot as plt
0638     init_rcParams(plt)
0639
0640     ok = opticks_main(doc=__doc__)
0641     log.debug(ok.brief)
0642
0643     #test_ABProfile( ok, plt )
0644     log.info("tagdir: %s " % ok.tagdir)
0645
0646     pr = Profile(ok.tagdir, "pro")
0647     log.info("[pr")
0648     print(pr)
0649     log.info("]pr")
0650
0651     if not pr.valid:
0652         log.fatal(" pr not valid exiting ")
0653         sys.exit(0)
0654     pass
0655
0656     if pr.multievent:
0657         multievent_plot(pr, plt)
0658     pass
0659
0660     simple_plot( pr, plt )
0661
0662
0663