7 Replies Latest reply on Sep 4, 2015 12:43 AM by johnrellis

    LrTasks.execute() is slow (10 times per second)

    jarnoh Level 1

      I have a metadata processing plugin that needs to execute another process to update metadata on a photo.  It's not extremely time sensitive, but since this is run on large amount (thousands) of photos, I wanted to make sure it is as fast as possible.  The metadata process is quite efficient and it run much faster from shell script than LR plugin, so I tried a little benchmark on LrTasks.execute:

      LrTasks.startAsyncTask(function() 
      local t0 = os.time()
      for i=1,100 do
        LrTasks.execute("/usr/bin/true")
      end
      local t1 = os.time()
      logger:debug("took",t1-t0,'s')
      end)
      

       

      Running this simple benchmark took 9 seconds!   For the record, it's about 30 times faster in standard Lua using os.execute()

       

      Are you guys familiar with this problem and have you implemented any workarounds?  I could perhaps launch a socket server and write parameters to that server, but it seems like a lot of work versus os.execute() which would suit my needs perfectly.

        • 1. Re: LrTasks.execute() is slow (10 times per second)
          johnrellis Most Valuable Participant

          I haven't observed this myself, though my plugins that execute scripts do a lot more work in the script itself, so I probably wouldn't have noticed. 

           

          Have you timed it in LR 5 or LR 4?  It would be interesting to know if this is version-specific (though the chances of it getting "fixed" are vanishingly small).

           

          The obvious workaround is to write a batch script that handles multiple photos per call to execute(), to amortize the cost of invocation.  It's pretty easy to invoke Exiftool that way, though properly handling errors in processing files takes extra care.

          • 2. Re: LrTasks.execute() is slow (10 times per second)
            jarnoh Level 1

            I tested LR5, it's 22ms per call.  Tested LR6 again, it's 130ms per call. Quite a difference, and it really adds up with lots of photos.  Lightroom was using 100% CPU during the test (= single core).   And, btw. these testes were run on a Mac, but isn't the Lightroom tradition that Windows version is always slower...

             

            I know exiftool has batch mode, but this is not exiftool   I guess I have to implement some kind of batch mode, its not really worth waiting 2 minutes for just scripts to start.

            • 3. Re: LrTasks.execute() is slow (10 times per second)
              johnrellis Most Valuable Participant

              I ran your test on my Macbook Pro with native OS 10.10.3 and Windows 8.1 running in Parallels, each measurement the average of 3 runs of your script:

               

              VersionMacWindows
              5.7.112.4 ms22.8 ms
              6.025.0 ms22.6 ms
              5.7.1/6.00.500.99

               

              Much different than your results.  The 50% slow-down on Mac is suspicious (but much less than what you measured).  Is it possible you still have background tasks running in your LR 6, e.g. building previews, face indexing, or some plugin doing background stuff?  I.e. is the CPU close to idle before you start your timing?

              isn't the Lightroom tradition that Windows version is always slower...

              I think that was the folklore many versions ago.  In LR 3, the API calls involving multiple tasks (e.g. having to be run on a separate task) took roughly 5-10 times longer on Windows than on Mac.  When we pointed out that LrTasks.yield() was similarly slower on Windows, one of the lead engineers tracked it down to a slower implementation of Lua tasks on Windows and fixed the problem in LR 4.

              • 4. Re: LrTasks.execute() is slow (10 times per second)
                jarnoh Level 1

                Interesting results indeed.  I'm running Macbook Pro 13" Retina Late 2013.  CPU usage is idle both before and after benchmark (Lightroom eating around 1-2% CPU just for kicks). 

                 

                Now I deleted presets, preferences and all plugins.  execute() runs in 25ms.  I added all my own created plugins, still around same (28ms).  I guess it's either the number of plugins, or some other plugin that breaks the camel's back.


                Anyway, 20+ms per invocation is a still bit more than I would like, so maybe the final conclusion is that one should avoid extra calls to execute().  It is not as fast as one would expect on 21st century.

                • 5. Re: LrTasks.execute() is slow (10 times per second)
                  johnrellis Most Valuable Participant
                  It is not as fast as one would expect on 21st century.

                  As a point of comparison, executing a shell script with 1000 /usr/bin/true lines takes 1.26 seconds, or 1.26 ms per /usr/bin/true, 20x faster.  I think we're paying for a Lua-based API that's had little love and attention from a core systems engineer for a number of years.

                  • 6. Re: LrTasks.execute() is slow (10 times per second)
                    jarnoh Level 1

                    I've done some more testing, it looks like there is some kind of internal problem with Lightroom.

                     

                    I've installed one single plugin to run the benchmark.  Starting fresh Lightroom 6.1.1, it is running 25ms per execute call.

                     

                    Now, if I open LR plugin manager 20 times by repeatedly pressing cmd+shift+option+. and enter to close dialog.

                     

                    Now, same benchmark runs 50ms per execute call.

                    • 7. Re: LrTasks.execute() is slow (10 times per second)
                      johnrellis Most Valuable Participant

                      The increase in in execution time is unrelated to reloading the plugin in the plugin manager.  Rather, LrTasks.execute() just slows down the more you call it.

                       

                      In LR CC 2015.1.1 / OS X 10.10.4, I timed LrTasks.execute() running continuously for over an hour, in three different catalogs, with no other plugins enabled.  One catalog was empty, one had 200 photos, and one had 25K photos.

                       

                      Here’s a plot of the seconds per call versus the number of seconds since the start:

                      Picture1.png

                      Here’s the same plot, but with a moving average used to smooth the lines:

                      Picture2.png

                       

                      On all three catalogs, the seconds/call starts at 0.01 or 0.02 but zooms up to 0.03–0.05 within a minute or so.  Then for the empty catalog, after about 47 minutes, seconds/call drops back down to about 0.013; for the catalog with 200 photos, it drops from 0.05 to 0.03 after 25 minutes.

                       

                      In all three catalogs, seconds/call exhibits regular fluctuations, with a period of about 150 seconds for the empty catalog, 360 seconds for the 200-photo catalog, and 65 seconds for the 25K catalog.

                       

                      This suggests that LrTasks.execute() may be competing with background housekeeping threads in LR.  Perhaps these threads are holding a lock or some other critical resource.

                       

                      Another hypothesis is that these fluctuations may be partially caused by garbage collection and memory allocation.  In particular, I’m wondering if there’s some bad behavior with respect to weak references being used to manage open file handles.  It’s conceivable that a mediocre implementation of weak references takes time proportional to the amount of memory allocated.  The empty catalog ended up with 212 MB allocated, the 200-photo catalog with 307 MB, and the 25K-photo catalog with 1 GB.

                       

                      local n = 100
                      
                      LrTasks.startAsyncTask (function() 
                          local start = LrDate.currentTime () 
                          local i = 0
                          while true do
                              local t = LrDate.currentTime ()  
                              for j = 1, n do  
                                    LrTasks.execute ("/usr/bin/true")
                                    i = i + 1 
                                    end 
                              local t = LrDate.currentTime () - t 
                              Debug.logn (i, LrDate.currentTime () - start, t / n)  
                              end  
                          end)