-
Apparently there are people who still keep a record of who is the heir to the Mexican empire ("... the webmaster favours a return to monarchy..."). The current heir lives in Australia. A crazy world, I tell you.
-
Improving login time, part 6: No history for the Nautilus desktop
(Index to the "Improving login time" series)
Simon Holm Thøgersen looked a bit more into yesterday's timeline, and he found that Nautilus causes all of ~/.thumbnails to be scanned when creating the desktop window. The thumbnails will need to be read eventually when displaying the files in ~/Desktop, but definitely not when the desktop is being initialized.
Why does the desktop window try to read the thumbnails so early?
At the bottom of the "Go" menu, Nautilus creates a few menu items with a history of the last folders you have visited. When you open a new window, it creates a menu item for the folder which you are visiting on that window. That menu item has a lovely icon which comes from the thumbnails database.
But once again, the desktop window doesn't have a menu bar! We are doing unnecessary work to maintain its menus, and it can be pretty expensive to do so.
With this patch, the first delay from yesterday does not appear in the timeline anymore; on my machine that's 0.1 seconds with a warm cache. The other delay comes from loading the image for the desktop background, which can't really be avoided.
-
Improving login time, part 5: A more detailed timeline for Nautilus
(Index to the "Improving login time" series)
A few days ago I revived these beasts:
- Patch to make Nautilus provide information for plotting startup timelines
- Patch for eel
- Script to plot timelines
With those patches applied, you can do this:
1. run gnome-session-properties and set nautilus to "normal" instead of "restart" 2. kill nautilus $ unset SESSION_MANAGER ... this will make nautilus not restart when you launch it from this shell $ cat > ~/nautilus-debug-log.conf [debug log] enable domains = checkpoint ... hit Control-D to write the config file $ strace -ttt -f -o /tmp/log.txt nautilus -n ... wait for the desktop to load, then press Control-C ... $ python plot-timeline.py -o timeline.png /tmp/log.txt ... this will spit timeline.png, which you can view
I've been trying to figure out why Nautilus doesn't paint the desktop until a few seconds after it hits gtk_main(). The latest version of the timeline shows that we are getting pretty close to finding the culprit (click on the picture for the full image):
The first blank space is where nautilus-window-manage-views.c:update_for_new_location() calls set_displayed_location(). That takes about 1/10 of a second, which is pretty long considering that we are only watching a two-second run of the whole program.
The second blank space is where fm-icon-view.c:fm_icon_view_begin_loading() connects the desktop background to monitor metadata changes, by calling nautilus_connect_desktop_background_to_file_metadata(). Again, this takes about 1/10 of a second.
Why are those calls so slow? Can someone add more checkpoints like in the patches to find out?
The full timeline has other interesting spots. Loading/scaling/painting the desktop bakground takes a good chunk of time inside eel. Adding each desktop icon takes a little time, but it adds up to a good chunk as well. There are still some large delays before we hit the main loop. There's a lot of room for fixing!
-
Miguel thinks the new GUI toolkit for Mono is very cool, and I wish him the best of luck.
Now we only have to see how much time it takes for the pie-menu nutcases to start asking questions. That is when we'll know that the new toolkit has achieved success.
-
This year I will be mentoring two students who have already been rocking the world:
Sayamindu Dasgupta (unmadindu on irc.gnome.org) will work on pre-configuration and lockdown for Nautilus and GtkFileChooser. This is about letting sysadmins configure pre-defined shortcuts for their users ("click here for the city government's forms to fill out"), and about constraining which parts of the filesystem users are allowed to view ("only your $HOME and our company's network shares"). Sayamindu has recently been working on polishing Sabayon, so he's already familiar with the problems that sysadmins face when pre-configuring things and locking them down.
Mathias Hasselmann (tbf on irc.gnome.org) will work on a new geometry manager for GTK+. GTK+ currently supports a simple size_request / size_allocate scheme; Mathias will extend it to support height-for-width sizing (for widgets like wrapped labels whose height depends on the width they are given), minimum / natural sizing (size_request currently only defines the minimum size for a widget, which can be very different from the size it would actually prefer to have), and alignment of widgets based on text baselines (so that labels and their associated entry controls can be nicely aligned).
-
Making Sabayon more robust and easier to debug
Yesterday I finished the work to make Sabayon have a logging system. The main sabayon program has two helper programs: sabayon-session to display the nested GNOME session for editing, and sabayon-apply to actually apply the user profile to the child session which is being edited.
Sabayon used to ignore the exit codes from these helper programs. So, if sabayon-apply failed, there was no way to know that the child session would be incorrect, and no way to report a bug based on this.
Sabayon actually had some pretty good logging, which it sent to stdout. So it was reasonably easy to change that system to be similar to the logging infrastructure which I put in Nautilus.
Also, the main sabayon process will now aggregate the logs from its helpers into its own logs. It monitors the exit codes of those helpers: 0 for a normal exit, 1 for an abnormal exit with a fatal error, and 2 for a normal exit with a recoverable error. The main program will tell you if something went wrong, and in that case it will dump the log to a file which you can pick up easily to attach to a bug report.
Many things can go wrong in the helper processes. Sabayon is purely glue (or eggs and hot air mixed with sugar): it is so high up among the abstraction layers that anything can go wrong under it. So we need to distinguish between fatal errors (actual programming bugs) or recoverable ones (such as a non-fatal condition which we didn't quite handle). For example, Sabayon will often fail to save a bit of the user profile because it didn't notice the creation or removal of a file within the session. But this shouldn't keep the rest of the user profile from being saved: that's a recoverable error.
These recoverable things are bugs which we need to find and fix, but first we need the infrastructure to actually find them. The new code lets us do that.
Some ideas from the experience of logging in Nautilus and Sabayon, as to what makes a nice logging system for users and developers:
-
If there is a bug in the program, the user should be presented with the log automatically, and with a way to file a bug report with that log. The new support for custom scripts in bug-buddy lets us do this.
-
If the developer needs extra information from the user, then he should be able to give very simple instructions to the user to tweak the logging parameters. Changing an environment variable is not "very simple" for various reasons: the user may not be used to command shells, he'll mistype the parameters anyway, and he'll forget to set the environment variable on the next run (which he'll launch from the icon launchers anyway). Also, environment variables are practically impossible for users to set for programs which get run automatically by the session manager.
The logging systems in Nautilus and Sabayon let you tweak the logging parameters by creating a file in the user's home directory. The developer can simply give that file to ther user and tell him, "please stick this attachment in ~/sabayon-debug-log.conf". This way the user doesn't need to type a command line; he can do that from his mail program or web browser. Also, if the logging parameters need to be changed, the developer can simply give a new version of that file to the user.
-
The log must indicate which logging parameters were used for that run. This way, when the developer gets the log file, he can ensure that user was indeed using the latest version of the configuration file. Also, a curious user can be reminded of which logging parameters were in effect without having to consult the program's documentation. Both Nautilus and Sabayon append the logging configuration to the end of the log file. Nautilus spits this:
This configuration for the debug log can be re-created by putting the following in ~/nautilus-debug-log.conf (use ';' to separate domain names): [debug log] enable domains = async; checkpoint max lines=5000
-
Log files must appear in an obvious place. It should also be obvious whether logging is enabled or disabled. Both of these problems can be solved by keeping the log files and the configuration file in the user's home directory: as soon as you see the logs and start thinking, "what is this crap doing here?", you'll see the configuration file and remember, "oh, yes, that's why they are happening".
-
Log files from different runs must not overwrite each other, and they must be dated. This lets you compare two versions with minimal hunting. Sabayon does this by creating a ~/sabayon-debug-log-YYYY-MM-DD-HH-MM-SS.txt log file; Nautilus doesn't do this yet.
-
-
Oralia went crazy two days ago and she made cream of zucchini spiked with Camembert cheese, plus a main course of baked peppers stuffed with cous-cous, cumin, mint leaves, and goat cheese.
The peppers were a lot more filling than they looked! It's nice when you get leftovers of really good food.
-
A couple weeks ago I went to Córdoba, Veracruz to give a talk on why schools should use free software for their Computer Science courses. Somehow I mentioned that Oralia's mother's side of the family is from the Isthmus of Tehuantepec, in the state of Oaxaca. A large contingent of students from the Tecnológico del Istmo had come all the way from Oaxaca to attend the talk, so I jokingly told them that had I known they would be there, I would have asked them to bring some totopos (baked flatbread) and the delicious cream cheese that is made in their region. After the talk, one of them told me, "we have some totopos in our bus". I thought they would share a few pieces of flatbread, but they gave me a huge bag of them — what a treat! Oralia and I are indebted forever.
-
Call for help from OpenSolaris hackers
There is an interesting discussion in performace-list about login time right now. One thing we cannot do in Linux is to get stack traces for all programs during login when they do IPC.
For example, we have programs requesting individual keys from GConf, and those roundtrips add up to 1 whole second. We now have programs talking through D-Bus during login, and we don't know if those calls are necessary and how long they take. We have programs doing unnecessary roundtrips to the X server.
We also have programs that do a lot of disk I/O, but we can mostly optimize it away through careful use of preload/readahead. However, IPC cannot be fixed this way.
So, your task if you have DTrace available, is to get the following information. We need to know:
- When a program starts blocking on a socket or pipe.
- When the program comes back to life after that operation.
- When a program goes to sleep by doing select()/poll().
- When a program wakes up from a select()/poll().
For each of these events, we need a timestamp and a stack trace. Later we can do the work of correlating who was waiting for what, and we can see if we can eliminate round-trips.
-
James: I intend to turn the content of my GUADEC talk on adding lockdown support to applications into a guide that app writers can use.