Files

Profile files are attached 

opsim-mysql.prof 

opsim-sqlite.prof 

opsim-sqlite-sync-off.prof

mysql-1year-stats.out

sqlite-1year-stats.out

sqlite-1year-sync-off-stats.out

1 year profile run running OpSim with MySQL

[hewelhog:~/LSST/opsim-profile] schandra% cat mysql-1year-stats.out 
=========== Top 50 Cumulative ============
Wed Jul 30 20:27:36 2014    opsim-mysql.prof
 
         17910270287 function calls (16253240991 primitive calls) in 27877.793 seconds
 
   Ordered by: cumulative time
   List reduced from 866 to 50 due to restriction <50>
 
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.002    0.002 27878.561 27878.561 main.py:8(<module>)
        1    0.001    0.001 27878.521 27878.521 main.py:94(startLsst)
        1    9.448    9.448 27551.356 27551.356 Simulator.py:230(start)
   267268  909.736    0.003 18763.494    0.070 ObsScheduler.py:372(suggestObservation)
131871186  761.035    0.000 13384.184    0.000 Instrument.py:1132(GetDelayForTarget)
131533681  239.096    0.000 11853.669    0.000 Instrument.py:1046(GetSlewDelay)
1707871087/131374699 3977.542    0.000 9443.057    0.000 Instrument.py:1006(GetDelayAfter)
      365    0.013    0.000 5467.402   14.979 Simulator.py:625(startNight)
      365    0.049    0.000 5467.064   14.978 ObsScheduler.py:173(startNight)
      365    0.045    0.000 5090.994   13.948 SchedulingData.py:341(startNight)
      365 1688.745    4.627 4048.782   11.093 SchedulingData.py:368(computeTargetData)
    26901 1329.933    0.049 4018.021    0.149 TransSubSeqProp.py:349(suggestObs)
   267240   33.890    0.000 3229.275    0.012 ObsScheduler.py:634(closeObservation)
  4089447   10.935    0.000 2898.794    0.001 Database.py:154(executeSQL)
  4089447   21.269    0.000 2876.903    0.001 cursors.py:139(execute)
  4089447    5.715    0.000 2816.240    0.001 cursors.py:315(_query)
  4089447   16.220    0.000 2799.116    0.001 cursors.py:277(_do_query)
  4089448 2721.087    0.001 2721.087    0.001 {method 'query' of '_mysql.connection' objects}
919622893 2349.539    0.000 2717.777    0.000 Instrument.py:808(TimeAccelMove)
131533681  521.367    0.000 2171.390    0.000 Instrument.py:465(SetClosestState)
 78292182 1043.686    0.000 1619.069    0.000 AstronomicalSky.py:563(getSkyBrightness)
262749398  416.058    0.000 1184.601    0.000 Instrument.py:893(GetDelayFor_TelAz)
262749398  390.210    0.000 1125.437    0.000 Instrument.py:880(GetDelayFor_TelAlt)
 59751095  534.953    0.000 1053.782    0.000 SuperSequence.py:774(RankTimeWindow)
      365  778.642    2.133 1042.164    2.855 SchedulingData.py:171(updateLookAheadWindow)
   267240    7.539    0.000  940.082    0.004 Database.py:455(addSlewHistory)
263672107  608.168    0.000  826.300    0.000 Instrument.py:120(Set)
131374699  303.243    0.000  758.831    0.000 Instrument.py:857(GetDelayFor_DomAz)
312427984  584.610    0.000  730.815    0.000 Instrument.py:335(GetShortestDistanceWithWrap)
131533681  193.296    0.000  728.688    0.000 Instrument.py:461(SetPosition)
131374699  235.001    0.000  696.338    0.000 Instrument.py:843(GetDelayFor_DomAlt)
   267240    8.813    0.000  651.676    0.002 Database.py:404(addObservation)
131374699  206.168    0.000  546.941    0.000 Instrument.py:926(GetDelayFor_Rotator)
131533681  161.052    0.000  535.392    0.000 Instrument.py:144(Copy)
131374699  397.648    0.000  514.520    0.000 Instrument.py:914(GetDelayFor_TelOpticsCL)
 78024942   92.669    0.000  508.101    0.000 AstronomicalSky.py:773(airmasst)
 20196705  330.272    0.000  479.142    0.000 Filters.py:205(computeFilterSeeing)
132067840  105.352    0.000  462.862    0.000 Instrument.py:372(GetTelAzDistanceWithWrap)
   267240    1.151    0.000  438.052    0.002 WLprop.py:331(closeObservation)
   267240    7.450    0.000  436.901    0.002 TransSubSeqProp.py:748(closeObservation)
1100294241  404.191    0.000  404.191    0.000 {divmod}
   267240   11.697    0.000  387.983    0.001 Instrument.py:1196(Observe)
   267240   32.945    0.000  387.097    0.001 Proposal.py:744(closeObservation)
131374699  204.248    0.000  377.482    0.000 Instrument.py:939(GetDelayFor_Filter)
 86343303  369.045    0.000  369.045    0.000 {sorted}
      365  123.527    0.338  366.584    1.004 TransSubSeqProp.py:148(startNight)
  1885097   13.170    0.000  361.407    0.000 Database.py:480(addSlewActivities)
356895592  340.320    0.000  340.320    0.000 SuperSequence.py:383(GetProgress)
81346000/813460  148.204    0.000  326.640    0.000 copy.py:145(deepcopy)
        1    0.000    0.000  326.407  326.407 Simulator.py:809(closeProposals)

 

1 year profile run running OpSim with sqlite

[hewelhog:~/LSST/opsim-profile] schandra% cat sqlite-1year-stats.out 
=========== Top 50 Cumulative ============
Thu Jul 31 00:36:52 2014    opsim-sqlite.prof
         17849180434 function calls (16189575860 primitive calls) in 42727.314 seconds
   Ordered by: cumulative time
   List reduced from 750 to 50 due to restriction <50>
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.027    0.027 42728.084 42728.084 main.py:8(<module>)
        1    0.001    0.001 42727.897 42727.897 main.py:72(startLsst)
        1   10.674   10.674 40385.487 40385.487 Simulator.py:230(start)
   267691  952.165    0.004 18976.057    0.071 ObsScheduler.py:372(suggestObservation)
  4094573   24.684    0.000 17490.517    0.004 Database.py:133(executeSQL)
  4094575 16312.478    0.004 16312.478    0.004 {method 'commit' of 'sqlite3.Connection' objects}   ---->>> THIS SEEMS TO BE THE CULPRIT
   267664   41.524    0.000 15772.459    0.059 ObsScheduler.py:634(closeObservation)
132081036  785.594    0.000 13590.698    0.000 Instrument.py:1132(GetDelayForTarget)
131737633  241.143    0.000 12043.938    0.000 Instrument.py:1046(GetSlewDelay)
1710525024/131578848 4046.620    0.000 9638.619    0.000 Instrument.py:1006(GetDelayAfter)
  1888416   24.643    0.000 7007.324    0.004 Database.py:446(addSlewActivities)
      365    0.014    0.000 5466.290   14.976 Simulator.py:625(startNight)
      365    0.065    0.000 5464.613   14.972 ObsScheduler.py:173(startNight)
      365    0.046    0.000 5108.350   13.995 SchedulingData.py:341(startNight)
      365 1646.852    4.512 4124.946   11.301 SchedulingData.py:368(computeTargetData)
    26942 1302.087    0.048 3999.149    0.148 TransSubSeqProp.py:349(suggestObs)
921051936 2443.034    0.000 2847.336    0.000 Instrument.py:808(TimeAccelMove)
   267664    8.772    0.000 2637.727    0.010 Database.py:370(addObservation)
        1    0.000    0.000 2331.868 2331.868 Simulator.py:809(closeProposals)
        1    0.000    0.000 2331.868 2331.868 ObsScheduler.py:868(closeProposals)
        1    1.643    1.643 2331.868 2331.868 TransSubSeqProp.py:871(closeProposal)
131737633  518.296    0.000 2164.063    0.000 Instrument.py:465(SetClosestState)
   267664    3.350    0.000 2135.152    0.008 Database.py:306(addSeqHistoryObsHistory)
   535328   10.718    0.000 2081.760    0.004 Database.py:474(addSlewState)
 78292606 1073.509    0.000 1708.228    0.000 AstronomicalSky.py:563(getSkyBrightness)
   267664    1.628    0.000 1223.090    0.005 WLprop.py:331(closeObservation)
   267664    8.133    0.000 1221.462    0.005 TransSubSeqProp.py:748(closeObservation)
263157696  408.613    0.000 1213.774    0.000 Instrument.py:893(GetDelayFor_TelAz)
   267664   33.967    0.000 1173.454    0.004 Proposal.py:744(closeObservation)
263157696  385.837    0.000 1155.546    0.000 Instrument.py:880(GetDelayFor_TelAlt)
   267664    8.598    0.000 1149.408    0.004 Database.py:421(addSlewHistory)
 59872098  560.087    0.000 1095.936    0.000 SuperSequence.py:774(RankTimeWindow)
  4094575 1094.731    0.000 1094.731    0.000 {method 'execute' of 'sqlite3.Cursor' objects}
   267664    3.944    0.000 1043.883    0.004 Database.py:330(addObsHistoryProposal)
   267664    4.363    0.000 1033.706    0.004 Database.py:459(addSlewMaxSpeeds)
      365  734.591    2.013  983.356    2.694 SchedulingData.py:171(updateLookAheadWindow)
131578848  303.596    0.000  777.673    0.000 Instrument.py:857(GetDelayFor_DomAz)
264086333  570.842    0.000  774.640    0.000 Instrument.py:120(Set)
312418099  607.572    0.000  752.635    0.000 Instrument.py:335(GetShortestDistanceWithWrap)
131737633  200.437    0.000  704.240    0.000 Instrument.py:461(SetPosition)
131578848  210.524    0.000  696.954    0.000 Instrument.py:843(GetDelayFor_DomAlt)
131578848  217.001    0.000  571.463    0.000 Instrument.py:926(GetDelayFor_Rotator)
 78024942   94.910    0.000  528.617    0.000 AstronomicalSky.py:773(airmasst)
131578848  391.398    0.000  514.055    0.000 Instrument.py:914(GetDelayFor_TelOpticsCL)
131737633  163.240    0.000  503.802    0.000 Instrument.py:144(Copy)
 20225796  340.291    0.000  494.574    0.000 Filters.py:205(computeFilterSeeing)
132272640  103.373    0.000  473.906    0.000 Instrument.py:372(GetTelAzDistanceWithWrap)
   267664   12.422    0.000  395.621    0.001 Instrument.py:1196(Observe)
1100901515  390.189    0.000  390.189    0.000 {divmod}
131578848  213.199    0.000  388.751    0.000 Instrument.py:939(GetDelayFor_Filter)

 

1 year profile run running OpSim with sqlite with snynchronous=off

[hewelhog:~/LSST/opsim-profile] schandra% cat sqlite-1year-sync-off-stats.out 
=========== Top 50 Cumulative ============
Thu Jul 31 19:21:52 2014    opsim-sqlite-sync-off.prof
 
         17825688454 function calls (16168875566 primitive calls) in 32981.465 seconds
 
   Ordered by: cumulative time
   List reduced from 750 to 50 due to restriction <50>
 
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.007    0.007 32982.281 32982.281 main.py:8(<module>)
        1    0.001    0.001 32982.234 32982.234 main.py:72(startLsst)
        1    9.818    9.818 31897.593 31897.593 Simulator.py:230(start)
   267199  957.684    0.004 18880.002    0.071 ObsScheduler.py:372(suggestObservation)
131850595  764.856    0.000 13540.951    0.000 Instrument.py:1132(GetDelayForTarget)
131517129  246.106    0.000 12023.120    0.000 Instrument.py:1046(GetSlewDelay)
1707658784/131358368 3981.701    0.000 9630.541    0.000 Instrument.py:1006(GetDelayAfter)
  4086249   26.164    0.000 7706.445    0.002 Database.py:135(executeSQL)
   267172   42.503    0.000 7316.699    0.027 ObsScheduler.py:634(closeObservation)
  4086251 6241.882    0.002 6241.882    0.002 {method 'commit' of 'sqlite3.Connection' objects}
      365    0.014    0.000 5533.364   15.160 Simulator.py:625(startNight)
      365    0.063    0.000 5532.356   15.157 ObsScheduler.py:173(startNight)
      365    0.047    0.000 5169.081   14.162 SchedulingData.py:341(startNight)
      365 1658.819    4.545 4132.434   11.322 SchedulingData.py:368(computeTargetData)
    26890 1319.609    0.049 3932.835    0.146 TransSubSeqProp.py:349(suggestObs)
  1884915   28.639    0.000 3184.162    0.002 Database.py:448(addSlewActivities)
919508576 2451.861    0.000 2862.658    0.000 Instrument.py:808(TimeAccelMove)
131517129  513.487    0.000 2146.356    0.000 Instrument.py:465(SetClosestState)
 78292114 1085.336    0.000 1707.482    0.000 AstronomicalSky.py:563(getSkyBrightness)
  4086251 1376.806    0.000 1376.806    0.000 {method 'execute' of 'sqlite3.Cursor' objects}
262716736  413.436    0.000 1219.151    0.000 Instrument.py:893(GetDelayFor_TelAz)
262716736  400.085    0.000 1168.588    0.000 Instrument.py:880(GetDelayFor_TelAlt)
 59724292  542.825    0.000 1089.478    0.000 SuperSequence.py:774(RankTimeWindow)
        1    0.000    0.000 1081.402 1081.402 Simulator.py:809(closeProposals)
        1    0.000    0.000 1081.402 1081.402 ObsScheduler.py:868(closeProposals)
        1    1.925    1.925 1081.402 1081.402 TransSubSeqProp.py:871(closeProposal)
      365  753.529    2.064 1036.597    2.840 SchedulingData.py:171(updateLookAheadWindow)
   267172    4.262    0.000  996.370    0.004 Database.py:308(addSeqHistoryObsHistory)
   267172    8.819    0.000  981.450    0.004 Database.py:372(addObservation)
   534344   12.616    0.000  907.897    0.002 Database.py:476(addSlewState)
131358368  313.483    0.000  793.647    0.000 Instrument.py:857(GetDelayFor_DomAz)
263634896  576.088    0.000  790.337    0.000 Instrument.py:120(Set)
311736531  587.543    0.000  729.808    0.000 Instrument.py:335(GetShortestDistanceWithWrap)
131358368  215.538    0.000  711.133    0.000 Instrument.py:843(GetDelayFor_DomAlt)
131517129  199.142    0.000  709.446    0.000 Instrument.py:461(SetPosition)
   267172    1.514    0.000  637.503    0.002 WLprop.py:331(closeObservation)
   267172    7.643    0.000  635.988    0.002 TransSubSeqProp.py:748(closeObservation)
   267172   30.788    0.000  588.837    0.002 Proposal.py:744(closeObservation)
131358368  220.616    0.000  574.724    0.000 Instrument.py:926(GetDelayFor_Rotator)
   267172   10.793    0.000  534.081    0.002 Database.py:423(addSlewHistory)
131358368  390.247    0.000  514.125    0.000 Instrument.py:914(GetDelayFor_TelOpticsCL)
 78024942   90.989    0.000  510.661    0.000 AstronomicalSky.py:773(airmasst)
131517129  157.137    0.000  510.304    0.000 Instrument.py:144(Copy)
 20188954  333.085    0.000  486.722    0.000 Filters.py:205(computeFilterSeeing)
132051152  106.387    0.000  464.198    0.000 Instrument.py:372(GetTelAzDistanceWithWrap)
   267172    3.868    0.000  464.176    0.002 Database.py:332(addObsHistoryProposal)
   267172    5.482    0.000  436.798    0.002 Database.py:461(addSlewMaxSpeeds)
1098853057  393.682    0.000  393.682    0.000 {divmod}
   267172   11.265    0.000  388.791    0.001 Instrument.py:1196(Observe)
131358368  209.321    0.000  387.572    0.000 Instrument.py:939(GetDelayFor_Filter)