GNOME Bugzilla – Bug 567989
Tomboy is slow to start up
Last modified: 2010-01-25 08:03:16 UTC
On many relatively speedy system, Tomboy takes several seconds to startup. As this can affect login time, it needs to be addressed. Work on bug #565790 (reducing memory at startup) will help, but perhaps more work can be done. Tomboy should not take more than 2 seconds to start on a freshly rebooted 1.7GHZ Pentium M machine.
Created attachment 126589 [details] Timeline I've done some measurements on this, which are graphed in the attached image. The obvious slowdown is the creation of the addin manager (3 seconds), but there are other improvements possible as well.
Created attachment 126590 [details] [review] Tracing patch This uses an adapted version of Federicos timeline tracing tools. The patch to generate the graph above is attached. Basically it adds a TraceLogger which generates the needed syscall for logging. Plotting is done using Federicos script. More info: http://www.gnome.org/~federico/news-2006-03.html#09
This patch is against SVN Trunk, r2276
Created attachment 126640 [details] Tomboy warm start @Ruben: Thanks for the script! My findings are quite a bit different though. I guess it all depends on the amount of notes you have ;) In my case (621 Notes) Notes loading takes by far the biggest chunk of time in the startup, see the attached graph. Note that this is a graph of a restart.
Created attachment 126641 [details] Tomboy cold start This is a trace of Tomboy startup during normal login. Takes nearly double the time.
Also want to point out, that disabling the Export to HTML, Backlinks and Printing Add-Ins reduces my startup time by 1.2 seconds (which is ~25 percent of the whole startup time). Interestingly the graph shows all the time savings during Note loading...
(In reply to comment #6) > Interestingly the graph shows all the time savings during Note loading... From what I could tell, this is because addins are instantiated for notes, which happens during the note loading. So this is to be expected.
suka: as with the memory bug, if you could rerun these against latest SVN or 0.13.3 when it is released Monday, it would be awesome. And thanks again, Ruben, for this patch. :-)
Created attachment 126663 [details] Tomboy SVN with plugins Very nice boost with SVN here too, also basically no difference if plugins are activated or not (so only posting the grap with plugins activated)
Created attachment 126664 [details] Tomboy SVN startup bug Still there seems to be a bug in SVN which sometimes increases the startup time severly (in my case: basically doubles startup time). From the graph you can see that Mono is called one additional time, this can also be seen in the graph Ruben posted.
suka, I am interested in what is causing this second call to Mono. Perhaps it's something with Mono.Addins, which runs Mono processes to rebuild the add-in database, iirc. Could you please run Tomboy from the command line, and if the second call to Mono occurs, attach the output here?
(In reply to comment #11) > suka, I am interested in what is causing this second call to Mono. Perhaps > it's something with Mono.Addins, which runs Mono processes to rebuild the > add-in database, iirc. Could you please run Tomboy from the command line, and > if the second call to Mono occurs, attach the output here? > Well the problem is: That behaviour is not so easy to reproduce, tried a few dozens time with little luck. Ultimately I could only trigger the second call to Mono when I removed the addins* directories in ~/.tomboy. So I don't know if the following is really helpful as this is hardly a regular case... The only diffence I could see in the "normal" output is that the line WARNING: The add-in 'Tomboy.TasqueAddin,0.1' is trying to extend '/Tomboy/NoteAddins', but there isn't any compatible add-in defining this extension point could be seen twice. So the output looked like this: [DEBUG]: NoteManager created with note path "/home/suka/.tomboy". [INFO]: Initializing Mono.Addins WARNING: The add-in 'Tomboy.TasqueAddin,0.1' is trying to extend '/Tomboy/NoteAddins', but there isn't any compatible add-in defining this extension point [DEBUG]: AddinManager.OnAddinLoaded: Tomboy.Tomboy [DEBUG]: Name: Tomboy.Tomboy,0.10 [DEBUG]: Description: [DEBUG]: Namespace: Tomboy [DEBUG]: Enabled: True [DEBUG]: File: /usr/lib/tomboy/Tomboy.exe WARNING: The add-in 'Tomboy.TasqueAddin,0.1' is trying to extend '/Tomboy/NoteAddins', but there isn't any compatible add-in defining this extension point [DEBUG]: AddinManager.OnAddinLoaded: Tomboy.ExportToHtmlAddin [DEBUG]: Name: Export to HTML [DEBUG]: Description: Exports individual notes to HTML. [DEBUG]: Namespace: Tomboy [DEBUG]: Enabled: True [DEBUG]: File: /usr/lib/tomboy/addins/ExportToHtml.dll [DEBUG]: AddinManager.OnAddinLoaded: Tomboy.PrintNotesAddin
(In reply to comment #12) > Well the problem is: That behaviour is not so easy to reproduce, tried a few > dozens time with little luck. Ultimately I could only trigger the second call > to Mono when I removed the addins* directories in ~/.tomboy. Okay, then this is probably normal Mono.Addins behavior when it recreates the local add-in database. For most users, this should only happen the first time they run Tomboy, and perhaps whenever they upgrade their Mono.Addins install. Thanks for looking into it.
Would love to see new numbers with 0.15.0, we stopped rebuilding the add-in registry on every start (we only do that if --debug is passed to Tomboy, now).
Created attachment 134067 [details] Tomboy 0.15.0 @sandy: As you wish. Attached is a new trace for Tomboy 0.15.0. The good news: The second Mono call is gone, cutting away ~1 sec startup time on my machine. Unfortunately the graph also shows two new big time consumers during startup. The first one is initializing GTK# which went up from 0.2 to nearly 1.3 seconds. The other one is "Starting addins" which increased from 0.1 to 1.6 seconds. I have to point out that naturally parts of my system were upgraded in between, now with Mono 2.4 instead of 2.2 for instance. Hope that helps.
Wow, what a mixed bag. Thanks for the new chart. Which add-ins do you have enabled? Don't worry if you're seeing slow downs; we did not add much in this release, so if we caused any slow downs (as opposed to Mono/GTK# being responsible for them), they should be easy to fix. Going to implement some kind of automated performance testing to keep us aware of changes in startup performance.
(In reply to comment #16) > Wow, what a mixed bag. Thanks for the new chart. Which add-ins do you have > enabled? Just a few, local sync, export to html, backlinks, printing support. But I've also done testing with all add-ins disabled, which changes the picture only somewhat. The time for the GTK# call stays unchanged, while "starting add-ins" drops to ~1.0 secs. Still a lot of time for no active add-ins, though ;)
Sorry for being off-topic... Andreas, are you the guy who is writing the nice GNOME reviews for my favourite Austrian newspaper? Thanks!
(In reply to comment #18) > Sorry for being off-topic... Andreas, are you the guy who is writing the nice > GNOME reviews for my favourite Austrian newspaper? Thanks! > Guilty as charged ;)
Created attachment 134133 [details] [review] Tomboy 0.15.0 version of patch
Andreas, I've just done some testing of 0.14.1 vs 0.15.0, with the same basic tracing. 0.15.0 is consistently 25% faster to start up for me. There are negligible changes to the startup sequence besides rebuilding the Mono registry. Basically, I'm seeing 8 total seconds go to 6 total seconds with tracing on. If I put a call to Exit Tomboy just before starting the main loop, and start Tomboy with `time tomboy` a few times, I get results like this: Tomboy 0.14.1, with Exit (0) just before StartMainLoop real 0m4.787s user 0m4.236s sys 0m0.304s Tomboy 0.15.0, with Exit (0) just before StartMainLoop real 0m3.569s user 0m3.100s sys 0m0.204s So with and without tracking, I'm seeing a 25% improvement in Tomboy start up. I'd say that it is definitely something else on your system that's causing your extra slow down, and I will look into that too as soon as I can. But least things aren't getting *worse* in Tomboy itself. :-)
(In reply to comment #21) > If I put a call to Exit Tomboy just before starting the main loop, and start > Tomboy with `time tomboy` a few times, I get results like this: To be very clear, this was done without the tracing patch applied. > So with and without tracking, I'm seeing a 25% improvement in Tomboy start up. Obviously, I meant with or without *tracing*.
model name : Intel(R) Core(TM)2 Duo CPU T7700 @ 2.40GHz PowerStep puts it at anywhere between 800 and 2400 MHz while starting Tomboy. With Tomboy 0.15.7, it's taking me about 1.9 seconds to start Tomboy, assuming it starts with no notes already open and no search. With the search window, it's taking less than 2.2 seconds. I have ~400 notes. I'm going to consider this bug closed, as I think we reached the original goal of 2 seconds (on average). If anyone still feels Tomboy is too slow to start up, please open a new bug with your specific request (for example: "Start in less than 2 seconds on an Aspire One netbook"). I should still file a bug for creating automated performance tests, though. Here are some fairly unscientific timings I took (because tracing slows things down). When starting Tomboy with --search, it activates via dbus and the command quits after the Search window is shown. When starting without --search, I hit ctrl+c as soon as the Tomboy icon appeared completely in the notification area. $ time tomboy --search real 0m2.187s user 0m0.192s sys 0m0.012s $ time tomboy --search real 0m2.133s user 0m0.208s sys 0m0.012s $ time tomboy [INFO]: Initializing Mono.Addins ^C real 0m1.927s user 0m1.212s sys 0m0.076s $ time tomboy [INFO]: Initializing Mono.Addins ^C real 0m2.010s user 0m1.196s sys 0m0.100s $ time tomboy [INFO]: Initializing Mono.Addins ^C real 0m1.856s user 0m1.244s sys 0m0.060s
Created attachment 152198 [details] [review] Restructure RemoteControl and command line execution One important thing to note is that we are no longer setting MONO_DISABLE_SHM=1 (see bug #514434), which means that Tomboy may write to disk every 40 seconds unless you upgrade to Mono 2.4.3 or later. This change was made so that we can depend on a named mutex for single-instance detection.
Created attachment 152199 [details] [review] Delay most work until after tray icon appears for 0.65 second startup Refactor NoteManager to push its work to an Initialize method, and provide Invoke methods that allow code to be executed only when the NoteManager is fully initialized. Use these Invoke methods to make clicking the tray icon and using global keybindings safe. RemoteControl work is on the way. Also delay SyncManager and ApplicationAddin initialization.
Created attachment 152200 [details] [review] Restructure RemoteControl and command line execution One important thing to note is that we are no longer setting MONO_DISABLE_SHM=1 (see bug #514434), which means that Tomboy may write to disk every 40 seconds unless you upgrade to Mono 2.4.3 or later. This change was made so that we can depend on a named mutex for single-instance detection.
The two new patches are for super-fast startup, but they might need review, and I definitely need to test them out on Windows and Mac, too. Apologies for the duplicate comments, I was playing with git-bz.
Everything working great on Windows and Mac, will probably push this tomorrow after I get someone else to try it out.