browse is slow after update from ship.2 to update.1 or joyride

[erikos]

Steps to reproduce:

• install a ship.2 build (e.g. 653)
• use the browser a bit to create the profile
  • profile is created in ~/.sugar/default/gecko
• update to a update.1 build (e.g. 684)
• use the browser
  • profile is created in isolation/1/gid_to_data_dir/[uid]/gecko
• takes really long to load a page

[erikos]

Test samples:

** Test 1
 - machine A(684), B(656->684)
 - connect to network
 - 1. Browse on machine B much slower to start
 - shutdown, restart
 - 2. Both have the same speed now

** Test 2
 - machine A(656->684), B(684)
 - connect to network
 - 1. Browse on machine A much slower to start
 - shutdown, restart
 - 2. A still slow

** Test 3 (check if only browse is affected)
 - machine A(656->684), B(684)
 - only browse is slow A, other activities work as expected

** Test 4 (update from 656 to joyride-1551)
 - same result
 - same result after restart

** Test 5 (Don't start browse in 656, so no profile around)
 - same result
 - same result after restart

Summary:

• I do not think it is related to the network as it is the same issue when I access local sites.
• removing the old profile does not help/without an old profile around we have the same issue
• not only 684, current joyride 1551 shows the same behavior
• top states that only the browse process is using the CPU and memory
• strace showed only differences in addresses accessed (enabled rainbow logging)
• sometimes it went away - like in Test1 or in other tests after a while which does not help to understand the issue:(

[erikos]

** Test 6
- update from 656 to 648
- rainbow off
- browse acts normal

** Test 7
- update from 656 to 1551
- rainbow off
- browse acts normal

This looks like rainbow is a hint, michael any idea?

[erikos]

More samples:

*** Test 6B
rainbow on
    browse is slow
rainbow off
    browse acts normal
rainbow on
    browse is slow

*** Test 7B
rainbow on
    browse is slow
rainbow off
    browse acts normal
rainbow on
    browse is slow

[jpritikin]

More data: I have a G1G1 machine. I upgraded from 653 to joyride 1532. Browse was slow. I turned off rainbow. Browse is normal.

[marco]

• You say "slower to start" in some of the tests, is that really what you mean or do you mean slow to load a page?
• Anything strange in the browser profile?
• Does it take full cpu when it's loading?
• Is interacting with a web page also slower (for example playing with trac forms)?
• Is about:config slow to load?
• Can you add debug logs in progresslistener.py and post the results (preferably for a local page so that we don't get confused by the network)?

[erikos]

• i meant slow to load a page (any page if local or on the network) not only browse startup

• did find nothing strange in the browser profile

• i tested with two machines in parallel and it was more than visible, numbers can be found in the logs

• it does take full CPU (no other process is taking noticeable more cpu), and the interesting part i just discovered is that browse will use that much CPU all the time when running. When I check the usage of browse on the virtual console it uses 97% all the time even though the page is loaded already.

• yes interacting with a web page is also slower, with the library page tested as well with a page on the net

• about:* are slower as well

• debug logs are attached; look for [start] and [stop]

[erikos]

debug logs for [start] and [stop]

[erikos]

The logs i attached are from a machine that got updated from 653 to 686.

[erikos]

To allay my comment above: In another test the CPU usage of browse goes down again when the page is loaded. But this does not change that the loading of pages is damn slow.

[tomeu]

If you install the debugging packages for xulrunner and run it while profiling with sysprof, you should be able to see what's going on.

[sayamindu]

Could you check the system date and time ? I could reproduce this by setting my system time to 1999. I traced the process, and I think it is going into some kind of long loop since it cannot open any file in /home/olpc/isolation/1/uid_to_home_dir/10003/.fontconfig/ (I could see that it is trying to open /var/cache/fontconfig/<blah>, and then getting a No Such file or Directory in /home/olpc/isolation/1/uid_to_home_dir/10003/.fontconfig/<blah>)

It may be possible that xulrunner is opening the fontcache in /var/lib/cache/fontconfig - finding it to be obsolete (because the font directory is newer than the cache file), trying to create one in .fontconfig, getting an error, and then going back to step 1

[mrcsparker]

I dropped down to the root shell and typed:

fc-cache -fv

Browsing was fine again. I am now posting this via my OLPC, which was running too slow a few minutes before.

[sayamindu]

Replying to mrcsparker:

I dropped down to the root shell and typed: fc-cache -fv Browsing was fine again. I am now posting this via my OLPC, which was running too slow a few minutes before.

Was your system time OK ? Also, did you experience this after upgrading from ship.2 to update.1 ?

[sayamindu]

One of the reasons behind this happening after an upgrade may be due to the fact that the fontconfig cache file format has been changed in newer versions of upgrade.1 and joyride. So Browse may be trying to recreate them, not being able to (they being global caches in /var/cache...), then trying to create them in home/olpc/isolation/1/uid_to_home_dir/10003/.fontconfig/... and subsequently failing.

[erikos]

sysprof was as well reporting that xulrunners bottleneck was fontconfig. So I did the following test.

Machine A (update from ship2 to update.1)
   653:
       date: recent
       ~/.fontconfig: not present
---update
   690:
       date: recent
       ~/.fontconfig: present (timestamps of today) 644
       browse slow
       fc-cache -fv:
           - updating ./fontconfig 
           - not updating /var/cache/fontconfig
           - diff between ./fontconfig and /var/cache/fontconfig
           - still slow
       fc-cache -fv (as root):
           - updating /var/cache/fontconfig
           - no diff between ./fontconfig and /var/cache/fontconfig
           - faster, but not as fast as a fresh install

Machine B
   date: recent
   ~/.fontconfig: present    

As I said machine A is faster after updating the cache but not as fast as B. Test results with sysprof claims that there is still more time spent in fontconfig on machine A. As well a diff of both machines caches showed some differences.

[sayamindu]

I'm trying to replicate the upgrade. Are you doing the upgrade via olpc-update ?

[erikos]

Yes steps are:

• clean install of 653
• olpc-update -f update.1-690

[garyo]

Replying to 6046: I had this slow/unresponsive browser problem after updating to update.1-690, and it seems to have been fixed by a fc-cache -r.

[erikos]

More tests:

The fc-cache -r made browse faster but it was still slower to a machine with a clean install, sysprof showed that the machine is still in the fontconfig loop. After turning the machine off at night and restarting in the morning both were at the same browse loading pages speed.

- A: 653->690
    check: browse is slow
    fc-cache -r: faster but not as fast
    shutdown and restart in the morning: as fast, no lookups for fontconfig anymore

Test if rebooting after the fc-cache -r helps. Does not look like.

 - A: 653->690
    check: slow
    fc-cache -r (sudo): faster but still fontconfig a bottleneck (~/.fontconfig is present before doing the fc-cache not after invoking the command)
    shutdown and start: still fontconfig loop in strace
                        i made a copy of /var/cache/fontconfig before restart and diff shows that /var/cache/fontconfig has not been changed during the restart
    fc-cache -f: creates ~/.fontconfig which diff claims to be the same than /var/cache/fontconfig, still slower after that change

[erikos]

Overnight test:

• two machines updated from 653 to 690.
• tested as browse is slow after update.
• NOT touched fc-cache or anything else
• Shutdown
• restart this morning
• the mtime of the cache files do not have changed (/var/cache/fontconfig and ~/.fontconfig)
• browse is again at normal speed
• when introspect with strace no 'open' calls to fontconfig stuff can be seen as have been with the machines after the update

strace of wiki.laptop.org attached.

[erikos]

strace -e open for browse after little olpc dragons miracly touched the machine in the night

[marco]

Aaargh I think there are at least a couple of bugs here, one in mozilla and one in fontconfig. See this mozilla bug:

https://bugzilla.mozilla.org/show_bug.cgi?id=404857

[bjepson]

I've seen this behavior as well, most recently when going from Update.1 to the latest Joyride. Joyride 1609 and 1611 are both exhibiting this problem.

[bjepson]

Regression: I did a factory restore using fs.zip and os656.img, then upgraded to joyride-1612, and have the same problem with Browse.

[erikos]

date on the machine: Jan 30 18:16 GMT 2008

2	drwxr-xr-x  8 root root 0 2008-01-30 20:30 .
3	drwxr-xr-x 76 root root 0 2008-01-30 20:30 ..
4	drwxr-xr-x  2 root root 0 2007-11-02 12:00 abyssinica
5	drwxr-xr-x  2 root root 0 2007-11-02 12:00 arabic
6	drwxr-xr-x  2 root root 0 2008-01-30 20:32 dejavu-lgc
7	drwxr-xr-x  2 root root 0 2008-01-30 20:32 lohit-hindi

looks like the mtime of the /usr/share/fonts folder is in the future. olpc is again ahead of things. FcConfigUptoDate() is failing and xulrunner is calling that many times and is trying to Reinitialize -> browser slow. After touching this folder you can browse away just fine. That explains as well why we had the miracle fixes when doing 'overnight tests'.

Why do we get timestamps in the future?

[sayamindu]

I have a modified fontconfig binary at http://dev.laptop.org/~sayamindu/libfontconfig.so.1.2.0, which prints out the time deltas between FcConfig was initialized and the mtime of

• the conf files of fontconfig
• the toplevel font directory (/usr/share/fonts)
• the most recently changed font directories themselves (/usr/share/fonts/arabic and so on)

whenever FcConfigUptoDate() is called.

Simon installed this file in the affected XO, and he ran a testcase he had written which calls FcConfigUptoDate() (http://dev.laptop.org/~erikos/fc_test.c), and the output is at http://dev.laptop.org/~erikos/fc_test.log This indicates that some subdirectory (or directories) of /usr/share/fonts has its mtime set in the future (approximately by around three hours), which causes FcConfigUptoDate() to return FcFalse. And sure enough, the previous comment by Simon confirms that there are directories with timestamps set in the future.

Previously Marco had pointed out that Xulrunner's gfxFontconfigUtils.cpp calls FcConfigUptoDate() from UpdateFontListInternal(), and if it is unsuccessful, the FcConfig is reinitialized and the whole thing repeats itself again. So we have Xulrunner going through the fonts again and again, causing the slowdown.

It looks as if the olpc-update utility is somehow setting times of some of the directories incorrectly (timezone issues). Reassigning component to upgrade-utility.

[cscott]

No, the difference is that later builds use ntp to sync time. So the XO's clock was set three hours fast, they did the update, then shortly after boot ntp reset the time to 'proper' time. Not a bug with olpc-update, and the problem will apparently fix itself once 'real' time catches up.

The problem might also be that joyride actually handles time zone correctly; same effective cause.

Not a bug in olpc-update. Fix this in font-config.

[cscott]

Further, people change timezones, clocks drift, etc. You just can't assume that time never jumps backward. See trac #1525 for previous symptoms of this fundamental problem.

[sayamindu]

Replying to cscott:

Further, people change timezones, clocks drift, etc. You just can't assume that time never jumps backward. See trac #1525 for previous symptoms of this fundamental problem.

Valid. The solution to bug #1525 worked around this by enabling fontconfig to write a cache in $HOME/.fontconfig and move ahead with that (previous to bug #1525, fontconfig could not write cache files at all if the system time was backwards compared to the timestamps). However, for newer versions of our releases, it seems that fontconfig cannot write to $HOME/.fontconfig (I have not confirmed this yet - but this is what the comments seem to indicate).

Mozilla pre-caches the set of available fonts at startup, and uses FcConfigUptoDate() to figure out if new fonts have been added to the system (http://lists.freedesktop.org/archives/fontconfig/2004-July/000960.html). And the only straightforward way for fontconfig to know if there are new fonts in the system is to check the timestamps of the directories which contain the font files, and to compare it with the timestamp when the FcConfig was initialized by the application concerned.

Is there any way that the security system can allow applications to write to .fontconfig ?

[mstone]

Please installing http://teach.laptop.org/~mstone/rainbow.rpm

This rainbow snapshot will symlink ~/.fontconfig -> instance.

Alternately, I could make a rainbow which precreates ~/.fontconfig. Let me know what would be best.

[bjepson]

I tried the new rainbow snapshot, and it worked the first time. But when I quit and restarted the activity, I got these errors in the Web activity log:

groupadd: group 10001 exists useradd: user 10001 exists

---

<type 'exceptions.OSError'> Traceback (most recent call last)

/usr/lib/python2.5/site-packages/rainbow/service.py in CreateActivity(self=<rainbow.service.Rainbow at / at 0xb74ed5ec>, log_path=dbus.UTF8String('/home/olpc/.sugar/default/logs/org.laptop.WebActivity-1.log'), env=dbus.Dictionary({dbus.UTF8String('LANG'): dbus.U...c/.Xauthority')}, signature=dbus.Signature('ss')), argv=dbus.Array([dbus.UTF8String('sugar-activity'), d...1d24ae79f919ea')], signature=dbus.Signature('s')), bundle_path=dbus.UTF8String('/usr/share/activities/Web.activity'), bundle_id=dbus.UTF8String('org.laptop.WebActivity'), success_cont=<function <lambda> at 0xb74eb79c>, error_cont=<function <lambda> at 0xb74eb6f4>)

58 ret = inject.run(log, SPOOL, env, argv, envSUGAR_BUNDLE_PATH?, (1, 2), 59 env.get('RAINBOW_STRACE_LOG'), 500, 500, bundle_path, bundle_id,

---> 60 env.get('RAINBOW_CONSTANT_UID'))

env.get = <built-in method get of dbus.Dictionary object at 0xb7705a4c>

61 except Exception, e: 62 util.trace()

/usr/lib/python2.5/site-packages/rainbow/inject.py in run(log=<function log at 0xb74eb64c>, spool='/home/olpc/isolation/1', env=dbus.Dictionary({dbus.UTF8String('LANG'): dbus.U...c/.Xauthority')}, signature=dbus.Signature('ss')), argv=dbus.Array([dbus.UTF8String('sugar-activity'), d...1d24ae79f919ea')], signature=dbus.Signature('s')), cwd=dbus.UTF8String('/usr/share/activities/Web.activity'), safe_fds=(1, 2), strace_hint=None, owner_uid=500, owner_gid=500, bundle_path=dbus.UTF8String('/usr/share/activities/Web.activity'), bundle_id=dbus.UTF8String('org.laptop.WebActivity'), constant_uid=dbus.UTF8String('yes'))

255 uid, gid = reserve_credentials(log, spool, bundle_id, constant_uid) 256 home = grab_home(log, spool, bundle_id, uid, gid, owner_uid)

--> 257 configure_home(spool, owner_uid, owner_gid, uid, gid, home)

global configure_home = <function configure_home at 0xb762287c> spool = '/home/olpc/isolation/1' owner_uid = 500 owner_gid = 500 uid = 10001 gid = 10001 home = '/home/olpc/isolation/1/uid_to_home_dir/10001'

258 259 if cwd is None:

/usr/lib/python2.5/site-packages/rainbow/inject.py in configure_home(spool='/home/olpc/isolation/1', owner_uid=500, owner_gid=500, uid=10001, gid=10001, home='/home/olpc/isolation/1/uid_to_home_dir/10001')

177 os.chmod(join(home, path), 0770) 178

--> 179 os.symlink('instance', join(home, '.fontconfig'))

global os.symlink = <built-in function symlink> global join = <function join at 0xb7c0b224> home = '/home/olpc/isolation/1/uid_to_home_dir/10001'

180 181 def launch(log, home, uid, gid, argv, env, cwd, safe_fds, strace_hint):

<type 'exceptions.OSError'>: [Errno 17] File exists

[bjepson]

Let me try that code block again:

groupadd: group 10001 exists
useradd: user 10001 exists
---------------------------------------------------------------------------
<type 'exceptions.OSError'>               Traceback (most recent call last)

/usr/lib/python2.5/site-packages/rainbow/service.py in CreateActivity(self=<rainbow.service.Rainbow at / at 0xb74ed5ec>, log_path=dbus.UTF8String('/home/olpc/.sugar/default/logs/org.laptop.WebActivity-1.log'), env=dbus.Dictionary({dbus.UTF8String('LANG'): dbus.U...c/.Xauthority')}, signature=dbus.Signature('ss')), argv=dbus.Array([dbus.UTF8String('sugar-activity'), d...1d24ae79f919ea')], signature=dbus.Signature('s')), bundle_path=dbus.UTF8String('/usr/share/activities/Web.activity'), bundle_id=dbus.UTF8String('org.laptop.WebActivity'), success_cont=<function <lambda> at 0xb74eb79c>, error_cont=<function <lambda> at 0xb74eb6f4>)
     58                     ret = inject.run(log, SPOOL, env, argv, env['SUGAR_BUNDLE_PATH'], (1, 2),
     59                             env.get('RAINBOW_STRACE_LOG'), 500, 500, bundle_path, bundle_id,
---> 60                             env.get('RAINBOW_CONSTANT_UID'))
        env.get = <built-in method get of dbus.Dictionary object at 0xb7705a4c>
     61                 except Exception, e:
     62                     util.trace()

/usr/lib/python2.5/site-packages/rainbow/inject.py in run(log=<function log at 0xb74eb64c>, spool='/home/olpc/isolation/1', env=dbus.Dictionary({dbus.UTF8String('LANG'): dbus.U...c/.Xauthority')}, signature=dbus.Signature('ss')), argv=dbus.Array([dbus.UTF8String('sugar-activity'), d...1d24ae79f919ea')], signature=dbus.Signature('s')), cwd=dbus.UTF8String('/usr/share/activities/Web.activity'), safe_fds=(1, 2), strace_hint=None, owner_uid=500, owner_gid=500, bundle_path=dbus.UTF8String('/usr/share/activities/Web.activity'), bundle_id=dbus.UTF8String('org.laptop.WebActivity'), constant_uid=dbus.UTF8String('yes'))
    255     uid, gid = reserve_credentials(log, spool, bundle_id, constant_uid)
    256     home = grab_home(log, spool, bundle_id, uid, gid, owner_uid)
--> 257     configure_home(spool, owner_uid, owner_gid, uid, gid, home)
        global configure_home = <function configure_home at 0xb762287c>
        spool = '/home/olpc/isolation/1'
        owner_uid = 500
        owner_gid = 500
        uid = 10001
        gid = 10001
        home = '/home/olpc/isolation/1/uid_to_home_dir/10001'
    258 
    259     if cwd is None:

/usr/lib/python2.5/site-packages/rainbow/inject.py in configure_home(spool='/home/olpc/isolation/1', owner_uid=500, owner_gid=500, uid=10001, gid=10001, home='/home/olpc/isolation/1/uid_to_home_dir/10001')
    177         os.chmod(join(home, path), 0770)
    178 
--> 179     os.symlink('instance', join(home, '.fontconfig'))
        global os.symlink = <built-in function symlink>
        global join = <function join at 0xb7c0b224>
        home = '/home/olpc/isolation/1/uid_to_home_dir/10001'
    180 
    181 def launch(log, home, uid, gid, argv, env, cwd, safe_fds, strace_hint):

<type 'exceptions.OSError'>: [Errno 17] File exists

[mstone]

Sigh; sorry about bungling that one.

I've updated the rpm at

http://teach.laptop.org/~mstone/rainbow.rpm

Please try again.

[erikos]

Thanks michael the fix in the new package does survive as well a reboot. The new rainbow package solves problem (a) - that ~/.fontconfig can be read by Browse, this speeds up page loading. The other problem we already analyzed (b) is that FcConfigUptoDate does fail because of future timestamps. To test this you can install the rainbow package and touch /usr/share/fonts. Only when you apply both changes the speed to load a page will be the same as the one on a clean install.

So I guess what is left is to find out how we fix best (b).

[mstone]

rainbow-0.7.9 should appear in the next joyride with both the '~/.fontconfig -> ~/instance' and the 'relaxed tmpfs size restrictions' modifications.

[sayamindu]

Proposed patch against Fontconfig

[sayamindu]

I have patched Fontconfig to find if directory mtimes are in the future and print a warning. Unfortunately this patch means that people with incorrect directory timestamps or incorrect system time will have to restart Browse in order to make it detect new fonts added to the system. However, I think that is a fair compromise, since it changes minimal code in fontconfig.

A RPM containing the fix is at http://dev.laptop.org/~sayamindu/fontconfig-2.4.2-5.olpc2.i386.rpm

Please test it and let me know if it works.

I think this, with the new rainbow RPM should fix this issue.

[erikos]

Did install the rainbow rpm and the new fontconfig one, set the date to something in the past (pre /usr/share/font mtimes) and browse was behaving fine (690). Logs did indicate the mtime issue.

[sayamindu]

A question regarding the patch above - does it make sense to make fontconfig print out the warning that the directory/file timestamps are in the future ?

This has a side effect that everyone the user tries to access a page via Browse, the log will have a warning message appended to it. However I think that there must be some way to let the user know that something might be wrong with the system.

[cscott]

Future timestamps are not indicative that something is wrong with the system. They are an expected outcome of time synchronization and other normal events. However, usually you will catch up to 'future' time relatively quickly (a few hours), so I don't see the log mesages as a huge problem. However, unless we're actually planning to *do something* with the log messages, why write them?

[sayamindu]

The new fontconfig is in Joyride build 1627. Please let me know if it works.

[sayamindu]

The new patch works for me. Please consider this for Update.1.

[jg]

Sayamindu, has this patch gone upstream to fontconfig?

Dennis, please verify the package name actually tested in joyride is the one that Sayamindu lists above.

Approved.

[mstone]

Dennis - note that we need both rainbow-0.7.9-1 and whatever fontconfig package Sayamindu recommends to close this one.

[sayamindu]

Replying to jg:

Sayamindu, has this patch gone upstream to fontconfig?

Bug filed - https://bugs.freedesktop.org/show_bug.cgi?id=14424

[dgilmore]

What is the version of fontconfig needed here.

[sayamindu]

This would be fontconfig-2.4.2-5.olpc2 (http://koji.fedoraproject.org/koji/buildinfo?buildID=33808)

[dgilmore]

please test update.1 build 693

[sayamindu]

Tested. It works in build 693.