UI freezes while main embedded repl is loaded

laurentpetit commented 9 years ago

Might be worth changing it to a promise.

laurentpetit commented 9 years ago

@arichiardi Just to understand: I understand that the code may not be optimal, but do you see the UI freeze when the embedded repl is loaded? I don't, and would like to be able to reproduce / see the problem before debugging it.

arichiardi commented 9 years ago

I see the UI stuck until the message of the Repl started comes out (Kepler). I remembered the delay there and I associated the two. I can try to record something.

arichiardi commented 9 years ago

You can try this, launch ccw and immediately try to go to the preferences (or any other menu like File,...). In my case it never opens the menu...until the repl has started ..

laurentpetit commented 9 years ago

Fixed in master. If you can do a little test to see whether this improves the situation for you, that would be great.

arichiardi commented 9 years ago

Will do

arichiardi commented 9 years ago

Hi Laurent...I have seen your commit on master, and I think I did not explain myself very well. What I was saying is that the main repl, the one which starts at the beginning of CCW, is probably executing on the UI thread (through our atom+delay trick) and freezing it. I don't know if you've experienced this...

laurentpetit commented 9 years ago

Reopening since it only solves the issue when used through the "open REPL Client" command

laurentpetit commented 9 years ago

I'm not sure I follow you. It would indeed be interesting to being able to determine what causes the UI to freeze like that.

laurentpetit commented 9 years ago

I have near 6-9 seconds of UI freeze also. But when I rename ~/.ccw/ to e.g. ~/.ccw-svg/, thus temporarily removing the plugins, and then I restart, then there's no freeze.

So currently the major bottleneck, as far as my installation is concerned, is during User Plugins load.

arichiardi commented 9 years ago

Must be that then.. in my case, I don't have any plugin installed, that is why I had excluded that reason...In any case, I will investigate further and write here if I find out ok?

laurentpetit commented 9 years ago

As far as User Plugins are concerned, it takes a long time if I have several User Plugins:

TOTAL for User Plugins TOOK 12841ms
loading ccw.core TOOK 1ms
ccw.e4.model invoker creation TOOK 1ms
ccw.core.user-plugins invoker creation TOOK 141ms
start-user-plugins TOOK 12698ms

Near 13 seconds for starting all the user plugins, when I have only a handful of them.

I will try to find the culprit, and also see if User Plugins launch can be put to a background thread

laurentpetit commented 9 years ago

OK, did 2 things:

the body of start-user-plugins is now encapsulated in a future. This stops freezing the UI while User Plugins are still loading in the background
each User plugin load time, and each User plugin script load time are traced in trace.log to help identify problems with User Plugins

arichiardi commented 9 years ago

Great, tomorrow i will test it for sure

laurentpetit commented 9 years ago

Pushed, directly to master.

arichiardi commented 9 years ago

There is a problem from some missing lib such as compliment, probably some dev stuff still there in Eclipse's conf/build path...in any case I am testing now after having removed them...

laurentpetit commented 9 years ago

Yes I also had to adapt. It's done on the master branch, but I haven't rebased yet.

Le vendredi 8 mai 2015, Andrea Richiardi notifications@github.com a écrit :

There is a problem from some missing lib such as compliment, probably some dev stuff still there in Eclipse's conf/build path...in any case I am testing now after having removed them...

— Reply to this email directly or view it on GitHub https://github.com/laurentpetit/ccw/issues/761#issuecomment-100140840.

Laurent Petit

arichiardi commented 9 years ago

Does it work for you? I am trying with a workspace-job but it still hangs the UI after having loaded the plugins...weird..

arichiardi commented 9 years ago

My change:

(defonce ^{:doc "Atom containing the workspace-job for loading the user plugins."}
  load-user-plugins-job
  #(e/workspace-job
   "User Plugins Loader"
   (fn [^IProgressMonitor monitor]
     (if-let [user-plugins (some-> (plugins-root-dir) user-plugins)]
       (binding [dsl/*load-key* (str (java.util.UUID/randomUUID))]
         (try
           (doseq [p user-plugins]
             (.subTask monitor (str "Loading " p))
             (trace-execution-time (format "Loading User Plugin %s" p)
                                   (start-user-plugin p)))
           (ccw.CCWPlugin/log (str "Loaded User Plugins"))
           (catch Exception e
             (ccw.CCWPlugin/logError "Error while loading User Plugins" e))
           (finally (clean-model! @m/app dsl/*load-key*))))
       (clean-model! @m/app)))))

(defn start-user-plugins
  "Find user plugins, load them, and then clean the Eclipse Application model
   to remove traces of user plugin artifacts that have not yet been loaded
   (meaning they are now considered garbage).
   If no user plugin is found, remove all user plugin artifacts from the model."
  []
  (.schedule (load-user-plugins-job)))

arichiardi commented 9 years ago

The last trace I get is:

| Thread-4 | 2015-05-08 11:37:16.934 | ccw.core | /log/info | ccw.CCWPlugin | log | 457 | INFO   - Started ccw nREPL server: nrepl://127.0.0.1:5055 |
| Worker-0 | 2015-05-08 11:37:17.150 | ccw.core | /log/info | ccw.CCWPlugin | log | 457 | INFO   - Loaded User Script /home/kapitan/.ccw/laurentpetit/ccw-plugin-manager/ccw-plugin-manager.clj |
| Worker-0 | 2015-05-08 11:37:17.151 | ccw.core | /log/info | ccw.CCWPlugin | log | 457 | INFO   - Loaded User Plugin: /home/kapitan/.ccw/laurentpetit/ccw-plugin-manager |
| main | 2015-05-08 11:37:17.370 | ccw.core | /log/info | ccw.util.ClojureContributionFactorySpi | create | 39 | create object for bundleclass://ccw.core/clojure/ccw.e4.dsl/handler-factory/ansi-repl/display-status |

From where we can see that is working using handle-factory on the main thread...

arichiardi commented 9 years ago

In my case, I tracked down the problem to ClojureContributionFactorySpi: 43 final Var v = BundleUtils.requireAndGetVar(bundle, var);

Everything is stuck and it does not go on after this line...

laurentpetit commented 9 years ago

ah yes. Please get the latest version of ccw-plugin-manager, and see it it fixes things for you. I had to upgrade it.

arichiardi commented 9 years ago

The same might be in ANSI plugin then

laurentpetit commented 9 years ago

Weird, I have lots of plugins enabled, working from master, and no problem

2015-05-08 13:34 GMT+02:00 Andrea Richiardi notifications@github.com:

The same might be in ANSI plugin then

— Reply to this email directly or view it on GitHub https://github.com/laurentpetit/ccw/issues/761#issuecomment-100202529.

Laurent Petit

arichiardi commented 9 years ago

Can I ask you one thing? The future that wraps starts user's lupins was never dereffed...or is it? Maybe I have checked out an old commit

arichiardi commented 9 years ago

Lol, it was start-user-plugins

laurentpetit commented 9 years ago

A future will immediately create a thread, and start its body within this new thread. There's no particular need to deref it if one doesn't want to block waiting for the future termination and getting its value back.

2015-05-08 13:43 GMT+02:00 Andrea Richiardi notifications@github.com:

Can I ask you one thing? The future that wraps starts user's lupins was never dereffed...or is it? Maybe I have checked out an old commit

— Reply to this email directly or view it on GitHub https://github.com/laurentpetit/ccw/issues/761#issuecomment-100205445.

Laurent Petit

arichiardi commented 9 years ago

For me still stuck, tomorrow I will try something locally maybe it's just Kepler..

laurentpetit commented 9 years ago

No, I also notice the freeze now that user plugins-related freeze is not here anymore

Le vendredi 8 mai 2015, Andrea Richiardi notifications@github.com a écrit :

For me still stuck, tomorrow I will try something locally maybe it's just Kepler..

— Reply to this email directly or view it on GitHub https://github.com/laurentpetit/ccw/issues/761#issuecomment-100338869.

Laurent Petit

laurentpetit commented 9 years ago

I did some investigation. It is the require of cider.nrepl in ccw.core.launch which takes something like 9 seconds on my laptop. I really don't know why it is taking this long.

Now, this does not totally explain why this is also freezing the UI. Will need to investigate this also. My best current bet is that there's some code executed on the UI thread which is waiting for a namespace to be launched via ClojureOSGi and since calls through it are synchronized (which is desired since it prevents loading code concurrently), the UI is frozen.

code executed from the UI may be prevented from launching through ClojureOSGi. I'll try to add some test code in ClojureOSGi to check whether it's called from the UI Thread, and if so, dump a strack trace for debugging purposes.

It's also a little bit surrealist that cider.nrepl takes so much time to load. But that can probably be separated into another issue.

2015-05-08 23:09 GMT+02:00 Laurent PETIT laurent.petit@gmail.com:

No, I also notice the freeze now that user plugins-related freeze is not here anymore

Le vendredi 8 mai 2015, Andrea Richiardi notifications@github.com a écrit :

For me still stuck, tomorrow I will try something locally maybe it's just Kepler..

— Reply to this email directly or view it on GitHub https://github.com/laurentpetit/ccw/issues/761#issuecomment-100338869.

Laurent Petit

Laurent Petit

arichiardi commented 9 years ago

Oh great you found the problem...I thought I was going crazy :)) It really looks like a synchronization issue and you are right, it should not matter as long as nobody runs code on the ui...but eventually somebody is...

laurentpetit commented 9 years ago

Found. It was the User Plugins start code which was still started from the UI Thread, and waiting synchronously for the cider-nrepl and other embedded repl related dependencies to load!

arichiardi commented 9 years ago

Ooooh great! You ended up encapsulating everything in a Job (like me above)...I also found nice to have (.subTask monitor (str "Loading " p)) to signal which plugin is loading, but your are one level upper ... by the way my version was not working at all...maybe I did not have the future...weird shouldn't a WorkspaceJob be already launched in a separate thread?

laurentpetit commented 9 years ago

Indeed I think a WorkspaceJob is always launched in a separate thread (it's WorkspaceRunnables which aren't)

laurentpetit commented 9 years ago

I also encounter a fatal deadlock if I try to open new editors while there is still activity in the background. Reopening.

arichiardi commented 9 years ago

Mmm...weird, explicit deadlock exception from the jvm?

laurentpetit commented 9 years ago

no, but I will try again now that aot is almost behind me. Will play with jstack & al

laurentpetit commented 9 years ago

OK I understood how the mutual lock occurs:

the start-user-plugins Thread is loading a particularly long user plugin within ClojureOSGi.withBundle synchronized block. It is not blocked yet, just taking a long time to execute with the Monitor lock.
in the mean time, I try, for example, to open a new clojure file. This triggers a UI Event, on the UI thread. From the UI thread, it starts a new ClojureEditor, for instance, which starts a new ClojureInvoker, which calls ClojureOSGi.require. Now we start getting into trouble, because we need to wait for the other thread to release the Monitor lock. And we're in the UI thread!
The fatal move occurs in the start-user-plugins, when at some point a call to e.g. defcommand occurs. This has profound ramifications: the Eclipse framework immediately calls event handlers, synchronously, via a Display.syncExec!
So we have the UI thread waiting for the ClojureOSGi Monitor, which is detained by the start-user-plugins thread
And we have the start-user-plugins thread which is waiting for the UI thread

Boum!

laurentpetit commented 9 years ago

I think the problem is that ClojureOSGi is over protective.

it should only synchronize calls to require (to prevent a same namespace to be concurrently loaded)
it should also probably, within require, maintain a set of already required namespaces, and, before acquiring the lock, return immediately if there's nothing to be done.

arichiardi commented 9 years ago

Gotcha! Thank you very interesting :)))

arichiardi commented 9 years ago

Yes I was inspecting exactly that part, and we could take advantage of some more sofisticated caching techniques... Very interesting part indeed to work on...of course you have precedence as you understand the code better, but I can both join in throwing ideas and thin code review...fine tuning is always fun!

For instance, what about ditching synchronized altogether? We can use cas idioms instead :)

laurentpetit commented 9 years ago

Well, I indeed think we'll just use a form of cas, a ConcurrentMap or ConcurrentSet, for manipulations outside the synchronized block.

But the synchronized is there for another reason: the Clojure compiler, however astonishing this can sound, is not thread safe, as far as I can tell. And also, trying to require the same namespace at the same time from 2 different threads might lead to some interesting issues ... that I don't want to deal with :-)

arichiardi commented 9 years ago

Kind of weird indeed.. Clojure being quite dynamic I expected it ...

arichiardi commented 9 years ago

Again about your explanation, it is exactly the reason why I approached Clojure in the first place...to get rid of all these crazy wait cascading that are so complicated to debug...

laurentpetit commented 9 years ago

My best bet is that this code is among the oldest of clojure code, and also maybe a performance trade off?

arichiardi commented 9 years ago

Great, we will change this in another PR..can't wait to :)

ccw-ide / ccw

UI freezes while main embedded repl is loaded #761