Page 1 of 1

time outs

PostPosted: Mon Nov 05, 2018 10:20 am
by kw123
For Matt & Jay:

it has been discussed before, but with no clear solution:
Code: Select all
  Error (client)                  timeout waiting for plugin response from xxx for request UiGetValues1
   Error (client)                  timeout waiting for plugin response from xxx for request CallPluginFunc
   Error (client)                  runDialogForMenuAction() caught exception: NSInvalidArgumentException -- *** -[__NSPlaceholderDictionary initWithObjects:forKeys:count:]: attempt to insert nil object from objects[0]

is there a way for the plugin developer to diagnose WHERE the plugin times out.. or if it is actually the plugin .

As I don't have these timeouts on my MAC, I would love to add some general debug code that captures these situations to isolate the part where kit might be waiting ..

My understanding is that the user opens config / menu and indigo server tries to contact the plugin, but it does not answer. Hence the server does not know why... just it did not respond.


import cProfile
seems to work only for specific methods you identify, but here we don't know which of the methods is waiting .. or you call the whole thing like this:
python -m cProfile -o myscript.cprof myscript.py

but who would I use that in a plugin?


Now can we add some code to the plugin that measures where it spends its time? and writes that periodically to the logfile?

Karl

Re: time outs

PostPosted: Mon Nov 05, 2018 11:30 am
by kw123
do answer my question:

inside
self.runConcurrentThread()
encapsulate the code into another method, then call it.
upon exit / reload it will print the time info .. there are many more options to do the print

Karl



Code: Select all
####-----------------   main loop, is dummy           ---------
### self.MAChome is the home directory of the user
### self.pluginName is the plugin name  w/o dots
##    def runConcurrentThread(self):

      try:    
         indigo.server.log("testing if variable do_cProfile_"+self.pluginName+" is == ON to enable time tracking of all methods ")
         do_cProfile = indigo.variables["do_cProfile_"+self.pluginName].value == "on"
         self.sleep(5)
      except:
         do_cProfile = False

      if do_cProfile:
         import cProfile
         import pstats
         indigo.server.log("======>>>>   starting w cProfile ON  for time measurements <<<<=====")
         pr = cProfile.Profile()
         pr.enable()
         self.dorunConcurrentThread()
         pr.disable()
         indigo.server.log(" print stats to"+self.MAChome+"/"+self.pluginName)
         pr.dump_stats(self.MAChome+"/"+self.pluginName+".dump")
         sys.stdout = open(self.MAChome+"/"+self.pluginName+".txt", 'w')
         stats = pstats.Stats(self.MAChome+"/"+self.pluginName+".dump")
         stats.sort_stats('cumulative')
         stats.print_stats()
      else:
         self.dorunConcurrentThread()

      return



   def dorunConcurrentThread(self):


will print to a file pluginName.txt:
Code: Select all
Mon Nov  5 11:25:35 2018    /Users/karlwachs/utilities.dump

         2315050 function calls (1589006 primitive calls) in 18.768 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   18.768   18.768 plugin.py:1965(dorunConcurrentThread)
       52   17.664    0.340   17.664    0.340 {select.select}
        4    0.000    0.000   17.579    4.395 /Library/Application Support/Perceptive Automation/Indigo 7.2/IndigoPluginHost.app/Contents/Resources/PlugIns/plugin_base.py:422(sleep)
        3    0.039    0.013    1.128    0.376 plugin.py:928(checkPluginCPU)
        1    0.003    0.003    0.961    0.961 /Library/Application Support/Perceptive Automation/Indigo 7.2/IndigoPluginHost.app/Contents/Resources/PlugIns/simplejson/__init__.py:184(dumps)
        1    0.052    0.052    0.957    0.957 /Library/Application Support/Perceptive Automation/Indigo 7.2/IndigoPluginHost.app/Contents/Resources/PlugIns/simplejson/encoder.py:179(encode)
   362838    0.080    0.000    0.896    0.000 /Library/Application Support/Perceptive Automation/Indigo 7.2/IndigoPluginHost.app/Contents/Resources/PlugIns/simplejson/encoder.py:409(_iterencode)
1088882/362838    0.331    0.000    0.816    0.000 /Library/Application Support/Perceptive Automation/Indigo 7.2/IndigoPluginHost.app/Contents/Resources/PlugIns/simplejson/encoder.py:332(_iterencode_dict)
    90993    0.123    0.000    0.286    0.000 /Library/Application Support/Perceptive Automation/Indigo 7.2/IndigoPluginHost.app/Contents/Resources/PlugIns/simplejson/encoder.py:43(py_encode_basestring_ascii)
    90993    0.140    0.000    0.140    0.000 {method 'sub' of '_sre.SRE_Pattern' objects}
        2    0.000    0.000    0.127    0.064 /System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/subprocess.py:768(communicate)
....

Re: time outs

PostPosted: Wed Nov 07, 2018 9:53 pm
by matt (support)
kw123 wrote:
My understanding is that the user opens config / menu and indigo server tries to contact the plugin, but it does not answer. Hence the server does not know why... just it did not respond.

Yes, all of the communication into the plugin callbacks happen in the same main thread. So if you have a long operation that hangs then any other callbacks cannot be processed until it has been completed. Pulling out slow (or functionality that can hang on network calls) into their own threads is normally the best solution. Basically, the faster all callbacks can return the better. Whatever actions they need to perform can continue executing, just in another thread.

cProfile looks very useful. I haven't experimented with it yet, so thanks for posting an example.

Re: time outs

PostPosted: Wed Nov 07, 2018 10:09 pm
by kw123
posted some new versions, was able to cut some 20% cpu usage using cProfile to check code

BUT it would really help if we could get SOME info about what is executing (ie which method/function) when it times out .
Right now it is just SOMEWHERE in the plugin it is waiting / executing .

I have some code that is communicating with other remote devices and waits for their answers. When eg that remote device is down the plugin will wait xx seconds before it gives up.
Moving that into an asynchronous thread would be very complicated, as the next steps depend on the success/failure/result of that communication... in a single thread it is MUCH MUCH easier to manage.


Karl

Re: time outs

PostPosted: Wed Nov 07, 2018 11:46 pm
by RogueProeliator
Moving that into an asynchronous thread would be very complicated, as the next steps depend on the success/failure/result of that communication... in a single thread it is MUCH MUCH easier to manage.

You basically just summed up about 1/3 of computer science in a nutshell there. Welcome to programming. :-)

Re: time outs

PostPosted: Thu Nov 08, 2018 10:34 am
by kw123
here a more complete version how to use it in your plugin to track cpu usage..
Karl

Code: Select all
#### to use this in your plugin to track cpu usage of the methods / functions in your plugin
#### if variable >> "enableTimeTracking_"+self.pluginName  ==
###  -- "on" it will start tracking
###  -- "off" it will stop tracking
###  -- "print-option"  it will print  w sort ==option   (option can be "" will use cumtime)
###       eg "print" will print the stats sorted by cumulative cpu time , "print-calls" will print sorted by # of calls
###      print to self.userIndigoPluginDir+"timeStats.txt" in readable format
      """ options for sorting:  (print-option)
      'calls'         call count
      'cumtime'      cumulative time
      'file'         file name
      'pcalls'      primitive call count
      'line'         line number
      'name'         function name
      'nfl'         name/file/line
      'stdname'      standard name
      'time'         internal time
      """


# you need add at top:
import cProfile
import pstats


# you need to set this in startup(): 
      self.userIndigoPluginDir ="path to somewhere you can write/"
      self.pluginName ="shortname for your plugin"
## call this once in startup() and
      self.checkcProfile()
      
## and in runConcurrentThread:
   def runConcurrentThread(self): 
      try:
         while True:
            self.sleep(5)
            self.checkcProfile()    ### add
            ### your stuff
      except:
         pass
      self.checkcProfileEND()  ### add



###  >>>  the code must be inside the plugin class, when it is put into a class by itself , it does not see the plugin methods  <<<
###
   ###########################      cProfile stuff   ############################ START
   ####-----------------  ---------
   def getcProfileVariable(self):

      try:
         if self.timeTrVarName in indigo.variables:
            xx = (indigo.variables[self.timeTrVarName].value).strip().lower().split("-")
            if len(xx) ==1:
               cmd = xx[0]
               pri = ""
            elif len(xx) == 2:
               cmd = xx[0]
               pri = xx[1]
            else:
               cmd = "off"
               pri  = ""
            self.timeTrackWaitTime = 20
            return cmd, pri
      except   Exception, e:
         pass

      self.timeTrackWaitTime = 60
      return "off",""

   ####-----------------            ---------
   def printcProfileStats(self,pri=""):
      try:
         if pri !="": pick = pri
         else:       pick = 'cumtime'
         outFile      = self.userIndigoPluginDir+"timeStats"
         indigo.server.log(" print time track stats to: "+outFile+".dump / txt  with option: "+pick)
         self.pr.dump_stats(outFile+".dump")
         sys.stdout    = open(outFile+".txt", "w")
         stats       = pstats.Stats(outFile+".dump")
         stats.strip_dirs()
         stats.sort_stats(pick)
         stats.print_stats()
         sys.stdout = sys.__stdout__
      except: pass

   ####-----------------            ---------
   def checkcProfile(self):
      try:
         if time.time() - self.lastTimegetcProfileVariable < self.timeTrackWaitTime:
            return
      except:
         self.cProfileVariableLoaded = 0
         self.do_cProfile           = "x"
         self.timeTrVarName          = "enableTimeTracking_"+self.pluginName
         indigo.server.log("testing if variable "+self.timeTrVarName+" is == on/off/print-option to enable/end/print time tracking of all functions and methods (option:'',calls,cumtime,pcalls,time)")

      self.lastTimegetcProfileVariable = time.time()

      cmd, pri = self.getcProfileVariable()
      if self.do_cProfile != cmd:
         if cmd == "on":
            if  self.cProfileVariableLoaded ==0:
               indigo.server.log("======>>>>   loading cProfile & pstats libs for time tracking;  starting w cProfile ")
               self.pr = cProfile.Profile()
               self.pr.enable()
               self.cProfileVariableLoaded = 2
            elif  self.cProfileVariableLoaded >1:
               self.quitNow = " restart due to change  ON  requested for print cProfile timers"
         elif cmd == "off" and self.cProfileVariableLoaded >0:
               self.pr.disable()
               self.quitNow = " restart due to  OFF  request for print cProfile timers "
      if cmd == "print"  and self.cProfileVariableLoaded >0:
            self.pr.disable()
            self.printcProfileStats(pri=pri)
            self.pr.enable()
            indigo.variable.updateValue(self.timeTrVarName,"done")

      self.do_cProfile = cmd
      return

   ####-----------------            ---------
   def checkcProfileEND(self):
      if self.do_cProfile in["on","print"] and self.cProfileVariableLoaded >0:
         self.printcProfileStats(pri="")
      return
   ###########################      cProfile stuff   ############################ END