Closed Bug 446314 Opened 16 years ago Closed 15 years ago

log4moz.js:142 consuming CPU warning; Firefox periodically consuming all available CPU in madvise and mmap2 calls if Weave is active

Categories

(Cloud Services :: General, defect)

Product:
Cloud Services
Component:
General
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: aleksander.adamowski, Unassigned)

Details

I've recently upgraded Weave to version 0.2.5 and Firefox to the Gecko/2008072004 GranParadiso/3.0.2pre nightly.

Now if Weave extension is active, Firefox becomes barely usable because of being kept busy by Weave.

The symptoms are:

1) When I launch Firefox, I immediately get this warning:

"A script on this page may be busy, or it may have stopped responding. You can stop the script now, or you can continue to see if the script will complete.

Script: file:///home/PATH_TO_DEFAULT_PROFILE.default/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/log4moz.js:142"

2) If I choose to stop executing the script, the probles cease to exist in this session of Firefox, but Weave doesn't work too. If I choose the script to continue running, I don't see this warning anymore, but Firefox starts consuming all available CPU almost all the time, interrupted by short periods of inactivity when I can actually do some work.

3) Running "strace -s 128 -p FIREFOX_PID" shows that during those CPU consuming runs it spends most of the time performing a long streams of madvise() calls and mmap2() calls on monotonically changing memory addresses:

...
madvise(0xafa4a000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa47000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa45000, 4096, 0x4 /* MADV_??? */) = 0
madvise(0xafa42000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa3f000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa3c000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa39000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa37000, 4096, 0x4 /* MADV_??? */) = 0
madvise(0xafa34000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa31000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa2e000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa2b000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa29000, 4096, 0x4 /* MADV_??? */) = 0
madvise(0xafa26000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa23000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa20000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa1d000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa1b000, 4096, 0x4 /* MADV_??? */) = 0
madvise(0xafa18000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa15000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa12000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa0f000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa0d000, 4096, 0x4 /* MADV_??? */) = 0
madvise(0xafa0a000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa07000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xafa04000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xaf9ff000, 4096, 0x4 /* MADV_??? */) = 0
madvise(0xaf9fc000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xaf9f9000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xaf9f6000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xaf9f4000, 4096, 0x4 /* MADV_??? */) = 0
madvise(0xaf9f1000, 8192, 0x4 /* MADV_??? */) = 0
madvise(0xaf9ee000, 8192, 0x4 /* MADV_??? */) = 0
...
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x95400000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x95300000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x95200000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x95100000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x95000000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94f00000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94e00000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94d00000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94c00000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94b00000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94a00000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94900000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94800000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94700000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94600000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94500000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94400000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94300000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94200000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94100000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x94000000
mmap2(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x93f00000
...

These streams of madvise() and mmap2() calls run for long periods of time during which Firefox consumes all available CPU cycles and is almost unresponsive.

Exiting Firefox can take almost half an hour during which one can constantly see it performing those streams of syscalls, and in parallel performing the final Weave sync: 

==> brief-log.txt <==
2008-07-20 19:45:09     Service.TabEngine       INFO    Actual changes for server: 34

==> verbose-log.txt <==
2008-07-20 19:45:09     Service.TabEngine       INFO    Actual changes for server: 34

==> brief-log.txt <==
2008-07-20 19:45:31     Service.TabEngine       INFO    Uploading changes to server

==> verbose-log.txt <==
2008-07-20 19:45:31     Service.TabEngine       INFO    Uploading changes to server
2008-07-20 19:45:31     Service.JsonFilter      DEBUG   Encoding data as JSON

==> brief-log.txt <==
2008-07-20 19:45:49     Service.Main    INFO    Skipping scheduled sync; local operation in progress

==> verbose-log.txt <==
2008-07-20 19:45:49     Service.Main    INFO    Skipping scheduled sync; local operation in progress
2008-07-20 19:45:49     Service.CryptoFilter    DEBUG   Encrypting data
2008-07-20 19:45:52     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:46:22     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:46:22     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:46:22     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:46:52     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:46:52     Async.Generator WARN    Async method 'Res__request-106' may have yielded without an outstanding callback.

==> verbose-log.txt <==
2008-07-20 19:46:52     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:46:52     Async.Generator WARN    Async method 'Res__request-106' may have yielded without an outstanding callback.
2008-07-20 19:46:52     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:46:53     Async.Generator WARN    Async method 'Res__request-106' may have yielded without an outstanding callback.

==> verbose-log.txt <==
2008-07-20 19:46:53     Async.Generator WARN    Async method 'Res__request-106' may have yielded without an outstanding callback.

==> brief-log.txt <==
2008-07-20 19:47:22     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:47:22     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:47:22     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:47:52     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:47:52     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:47:53     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:48:23     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:48:23     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:48:23     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:48:53     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:48:53     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:48:54     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:49:24     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:49:24     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:49:24     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:49:54     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:49:54     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:49:55     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:50:25     Async.EventHandler      WARN    Connection timed out, aborting...

==> verbose-log.txt <==
2008-07-20 19:50:25     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:50:26     Service.DAV     DEBUG   PUT request for user-data/tabs/deltas/244

==> brief-log.txt <==
2008-07-20 19:50:49     Service.Main    INFO    Skipping scheduled sync; local operation in progress

==> verbose-log.txt <==
2008-07-20 19:50:49     Service.Main    INFO    Skipping scheduled sync; local operation in progress

...


==> verbose-log.txt <==
2008-07-20 19:51:27     Async.EventHandler      WARN    Connection timed out, aborting...
2008-07-20 19:51:27     Service.DAV     DEBUG   UNLOCK request for lock

==> brief-log.txt <==
2008-07-20 19:51:35     Sync.Status     INFO    Existing action finished, starting modal sync.

==> verbose-log.txt <==
2008-07-20 19:51:35     Sync.Status     INFO    Existing action finished, starting modal sync.
2008-07-20 19:51:35     Service.DAV     DEBUG   LOCK request for lock

==> brief-log.txt <==
2008-07-20 19:51:42     Service.BmkEngine       INFO    Beginning sync

==> verbose-log.txt <==
2008-07-20 19:51:42     Service.BmkEngine       INFO    Beginning sync
2008-07-20 19:51:42     Service.DAV     DEBUG   GET request for user-data/
2008-07-20 19:51:49     Service.DAV     DEBUG   GET request for user-data/bookmarks/
2008-07-20 19:51:56     Service.DAV     DEBUG   GET request for user-data/bookmarks/deltas/
2008-07-20 19:52:04     Service.RemoteStore     DEBUG   Downloading status file
2008-07-20 19:52:04     Service.DAV     DEBUG   GET request for user-data/bookmarks/status.json

==> brief-log.txt <==
2008-07-20 19:52:12     Service.BmkEngine       INFO    Local snapshot version: 6
2008-07-20 19:52:12     Service.BmkEngine       INFO    Server maxVersion: 6

==> verbose-log.txt <==
2008-07-20 19:52:12     Service.Resource        DEBUG   GET request successful
2008-07-20 19:52:12     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-20 19:52:12     Service.RemoteStore     DEBUG   Downloading status file... done
2008-07-20 19:52:12     Service.BmkEngine       INFO    Local snapshot version: 6
2008-07-20 19:52:12     Service.BmkEngine       INFO    Server maxVersion: 6
2008-07-20 19:52:12     Service.DAV     DEBUG   GET request for user-data/bookmarks/keys.json
2008-07-20 19:52:19     Service.Resource        DEBUG   GET request successful
2008-07-20 19:52:19     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-20 19:52:20     Service.RemoteStore     DEBUG   Using last sync snapshot as server snapshot (snap version == max version)
2008-07-20 19:52:20     Service.RemoteStore     TRACE   Local snapshot version == server maxVersion

==> brief-log.txt <==
2008-07-20 19:52:31     Service.BmkEngine       INFO    Reconciling client/server updates
2008-07-20 19:52:31     Service.BmkEngine       INFO    Changes for client: 0
2008-07-20 19:52:31     Service.BmkEngine       INFO    Predicted changes for server: 0
2008-07-20 19:52:31     Service.BmkEngine       INFO    Client conflicts: 1
2008-07-20 19:52:31     Service.BmkEngine       INFO    Server conflicts: 1
2008-07-20 19:52:31     Service.BmkEngine       WARN    Conflicts found!  Discarding server changes

==> verbose-log.txt <==
2008-07-20 19:52:31     Service.BmkEngine       INFO    Reconciling client/server updates

2008-07-20 19:52:31     Service.BMSync  DEBUG   Reconciling 1 against 1 commands
2008-07-20 19:52:31     Service.BmkEngine       INFO    Changes for client: 0
2008-07-20 19:52:31     Service.BmkEngine       INFO    Predicted changes for server: 0
2008-07-20 19:52:31     Service.BmkEngine       INFO    Client conflicts: 1
2008-07-20 19:52:31     Service.BmkEngine       INFO    Server conflicts: 1
2008-07-20 19:52:31     Service.BmkEngine       WARN    Conflicts found!  Discarding server changes

==> brief-log.txt <==
2008-07-20 19:52:36     Service.BmkEngine       INFO    Actual changes for server: 1
2008-07-20 19:52:36     Service.BmkEngine       INFO    Uploading changes to server

==> verbose-log.txt <==
2008-07-20 19:52:36     Service.BmkEngine       INFO    Actual changes for server: 1
2008-07-20 19:52:36     Service.BmkEngine       INFO    Uploading changes to server
2008-07-20 19:52:36     Service.JsonFilter      DEBUG   Encoding data as JSON
2008-07-20 19:52:36     Service.CryptoFilter    DEBUG   Encrypting data
2008-07-20 19:52:36     Service.DAV     DEBUG   PUT request for user-data/bookmarks/deltas/7
2008-07-20 19:52:51     Service.ResourceSet     DEBUG   PUT request successful
2008-07-20 19:52:51     Service.JsonFilter      DEBUG   Encoding data as JSON
2008-07-20 19:52:51     Service.DAV     DEBUG   PUT request for user-data/bookmarks/status.json

==> brief-log.txt <==
2008-07-20 19:52:55     Service.BmkEngine       INFO    Successfully updated deltas and status on server
2008-07-20 19:52:55     Service.SnapStore       INFO    Saving snapshot to disk
2008-07-20 19:52:55     Service.BmkEngine       INFO    Sync complete
2008-07-20 19:52:55     Service.CookieEngine    INFO    Beginning sync

==> verbose-log.txt <==
2008-07-20 19:52:55     Service.Resource        DEBUG   PUT request successful
2008-07-20 19:52:55     Service.BmkEngine       INFO    Successfully updated deltas and status on server
2008-07-20 19:52:55     Service.SnapStore       INFO    Saving snapshot to disk
2008-07-20 19:52:55     Service.BmkEngine       INFO    Sync complete
2008-07-20 19:52:55     Service.CookieEngine    INFO    Beginning sync
2008-07-20 19:52:55     Service.DAV     DEBUG   GET request for user-data/
2008-07-20 19:53:09     Service.DAV     DEBUG   GET request for user-data/cookies/
2008-07-20 19:53:15     Service.DAV     DEBUG   GET request for user-data/cookies/deltas/
2008-07-20 19:53:25     Service.RemoteStore     DEBUG   Downloading status file
2008-07-20 19:53:25     Service.DAV     DEBUG   GET request for user-data/cookies/status.json

==> brief-log.txt <==
2008-07-20 19:53:30     Service.CookieEngine    INFO    Local snapshot version: 22
2008-07-20 19:53:30     Service.CookieEngine    INFO    Server maxVersion: 22

==> verbose-log.txt <==
2008-07-20 19:53:30     Service.Resource        DEBUG   GET request successful
2008-07-20 19:53:30     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-20 19:53:30     Service.RemoteStore     DEBUG   Downloading status file... done
2008-07-20 19:53:30     Service.CookieEngine    INFO    Local snapshot version: 22

...

==> verbose-log.txt <==
2008-07-20 19:54:58     Service.Resource        DEBUG   GET request successful
2008-07-20 19:54:58     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-20 19:54:58     Service.RemoteStore     DEBUG   Downloading status file... done
2008-07-20 19:54:58     Service.TabEngine       INFO    Local snapshot version: 244
2008-07-20 19:54:58     Service.TabEngine       INFO    Server maxVersion: 243
2008-07-20 19:54:58     Service.DAV     DEBUG   GET request for user-data/tabs/keys.json

==> brief-log.txt <==
2008-07-20 19:55:02     Service.RemoteStore     ERROR   Server snapshot is older than local snapshot

==> verbose-log.txt <==
2008-07-20 19:55:02     Service.Resource        DEBUG   GET request successful
2008-07-20 19:55:02     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-20 19:55:02     Service.RemoteStore     ERROR   Server snapshot is older than local snapshot
2008-07-20 19:55:03     Service.DAV     DEBUG   UNLOCK request for lock


During that sync one can notice large amounts of timeouts. It's unclear whether they are due to Firefox being too busy and thus inactive for too long on a connection, or the Weave server being inaccessible.
Memory consumption grows infinitely also. Up to 600 Mb of virtual memory are committed before my system becomes unresponsive.
In my case, when shutting down, virtual process size has grown to 1.3 GB and after Firefox has finished trying to do the last sync it quickly dropped to the normal ~300MB before the process has cleanly exited.

My Firefox reports Weave hanging on log4moz.js:234 (different line)
Turning tab sync off resolves the problem.
I can reproduce everything up to & including the workaround in comment #4 from basilevs@ngs.ru.  Aleksander, please also try disabling the syncing of tabs (in Preferences... -> Weave -> Data).  If this suggestion solves your problem, then please close this bug, marking it a duplicate of bug #475314.  Thanks!
Guys, could you please re-test using the latest Weave snapshots?  It requires a new server, but should have better memory performance.
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → WORKSFORME
Component: Weave → General
Product: Mozilla Labs → Weave
Target Milestone: -- → ---
QA Contact: weave → general
You need to log in before you can comment on or make changes to this bug.