Bug 13040 – Safari WebKit Hanging/Feverish Disk Activity/Slows entire system...

• Component: Page Loading
• Status: RESOLVED CONFIGURATION CHANGED

[donnie]

I use Safari and am quite happy with it except one thing. I constantly hangs for 5 minutes or so each session. I do have many bookmarks. And have turned off Spotlight with a piece of software called Spotless. I posted here before and soeone said it was Spotlight taking up CPU. I knew it wasn't. But now it's completely off and still Safari/WebKit goes into a state of frenzy doing something like caching or whatever. It's constant disk activity and then it does stop. But always happens during each surfing session. Does not seem to be any way around this. Installed and use the latest updates that are qualified to work. This has also been a problem I have seen on the web for a couple of ears. Yet, with NO solutions to and for the problem. Is it possible we can get to the bottom of things? I am including the crash report, along with the text that comes up in open files and ports window while webKit is hanging. 

Hope someone can figure it out. This is a TOP NOTCH Browser. Let's get as many bugs out as possible. And I am trying to help. Not get in the way. I'm heated because I cannot find out what the problem is. And hopefully someone will know how to troubleshoot the issue. Wishing everyone the most good possible! Donnie Dixon

Crash Reporter text:

**********

Host Name:      donnie-dixons-power-mac-g4
Date/Time:      2007-03-09 01:47:52.503 -0500
OS Version:     10.4.8 (Build 8L127)
Report Version: 4

Command: Safari
Path:    /Applications/Safari.app/Contents/MacOS/Safari
Parent:  WindowServer [77]

Version: ??? (19919)

PID:    222
Thread: 0

Exception:  EXC_BAD_ACCESS (0x0001)
Codes:      KERN_PROTECTION_FAILURE (0x0002) at 0x00000014

Thread 0 Crashed:
0   com.apple.JavaScriptCore       	0x001761d8 WTF::fastFree(void*) + 56
1   com.apple.WebCore              	0x0148d5b8 WTF::HashTableRefCounterBase<(bool)1, WTF::HashTable<WebCore::StringImpl*, std::pair<WebCore::StringImpl*, int>, WTF::PairFirstExtractor<std::pair<WebCore::StringImpl*, int> >, WTF::CaseInsensitiveHash<WebCore::StringImpl*>, WTF::PairHashTraits<WTF::HashTraits<WebCore::StringImpl*>, WTF::HashTraits<int> >, WTF::HashTraits<WebCore::StringImpl*> >, WTF::PairBaseHashTraits<WTF::HashTraits<WebCore::String>, WebCore::String> >::derefAll(WTF::HashTraits<WebCore::StringImpl*>&) + 200
2   com.apple.WebCore              	0x013b43ac -[WebCoreResourceHandleAsDelegate connection:willSendRequest:redirectResponse:] + 252
3   com.apple.Foundation           	0x9298fbc4 -[NSURLConnection(NSURLConnectionInternal) _sendWillSendRequestCallback] + 76
4   com.apple.Foundation           	0x9298f9e4 -[NSURLConnection(NSURLConnectionInternal) _sendCallbacks] + 344
5   com.apple.Foundation           	0x9298f810 _sendCallbacks + 156
6   com.apple.CoreFoundation       	0x907dd4cc __CFRunLoopDoSources0 + 384
7   com.apple.CoreFoundation       	0x907dc9fc __CFRunLoopRun + 452
8   com.apple.CoreFoundation       	0x907dc47c CFRunLoopRunSpecific + 268
9   com.apple.HIToolbox            	0x93205740 RunCurrentEventLoopInMode + 264
10  com.apple.HIToolbox            	0x93204dd4 ReceiveNextEventCommon + 380
11  com.apple.HIToolbox            	0x93204c40 BlockUntilNextEventMatchingListInMode + 96
12  com.apple.AppKit               	0x936e7ae4 _DPSNextEvent + 384
13  com.apple.AppKit               	0x936e77a8 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 116
14  com.apple.Safari               	0x00006740 0x1000 + 22336
15  com.apple.AppKit               	0x936e3cec -[NSApplication run] + 472
16  com.apple.AppKit               	0x937d487c NSApplicationMain + 452
17  com.apple.Safari               	0x0005c77c 0x1000 + 374652
18  com.apple.Safari               	0x0005c624 0x1000 + 374308

Thread 1:
0   libSystem.B.dylib              	0x9000ab48 mach_msg_trap + 8
1   libSystem.B.dylib              	0x9000aa9c mach_msg + 60
2   com.apple.CoreFoundation       	0x907dcb78 __CFRunLoopRun + 832
3   com.apple.CoreFoundation       	0x907dc47c CFRunLoopRunSpecific + 268
4   com.apple.Foundation           	0x9298669c +[NSURLConnection(NSURLConnectionInternal) _resourceLoadLoop:] + 264
5   com.apple.Foundation           	0x9295f194 forkThreadForFunction + 108
6   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 2:
0   libSystem.B.dylib              	0x9000ab48 mach_msg_trap + 8
1   libSystem.B.dylib              	0x9000aa9c mach_msg + 60
2   com.apple.CoreFoundation       	0x907dcb78 __CFRunLoopRun + 832
3   com.apple.CoreFoundation       	0x907dc47c CFRunLoopRunSpecific + 268
4   com.apple.Foundation           	0x929877dc +[NSURLCache _diskCacheSyncLoop:] + 152
5   com.apple.Foundation           	0x9295f194 forkThreadForFunction + 108
6   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 3:
0   libSystem.B.dylib              	0x9002bbc8 semaphore_wait_signal_trap + 8
1   libSystem.B.dylib              	0x900306ac pthread_cond_wait + 480
2   com.apple.Foundation           	0x92966300 -[NSConditionLock lockWhenCondition:] + 68
3   com.apple.Syndication          	0x9a4dc42c -[AsyncDB _run:] + 192
4   com.apple.Foundation           	0x9295f194 forkThreadForFunction + 108
5   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 4:
0   libSystem.B.dylib              	0x9001f08c select + 12
1   com.apple.CoreFoundation       	0x907ef40c __CFSocketManager + 472
2   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 5:
0   libSystem.B.dylib              	0x9002e88c kevent + 12
1   com.apple.DesktopServices      	0x92872eb0 TFSNotificationTask::FSNotificationTaskProc(void*) + 56
2   ...ple.CoreServices.CarbonCore 	0x90bc48b0 PrivateMPEntryPoint + 76
3   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 6:
0   libSystem.B.dylib              	0x9002bbc8 semaphore_wait_signal_trap + 8
1   libSystem.B.dylib              	0x900306ac pthread_cond_wait + 480
2   ...ple.CoreServices.CarbonCore 	0x90bc4aa0 MPWaitOnQueue + 224
3   com.apple.DesktopServices      	0x9287352c TNodeSyncTask::SyncTaskProc(void*) + 116
4   ...ple.CoreServices.CarbonCore 	0x90bc48b0 PrivateMPEntryPoint + 76
5   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 7:
0   libSystem.B.dylib              	0x9002bbc8 semaphore_wait_signal_trap + 8
1   libSystem.B.dylib              	0x900306ac pthread_cond_wait + 480
2   com.apple.Foundation           	0x92966300 -[NSConditionLock lockWhenCondition:] + 68
3   com.apple.AppKit               	0x93784708 -[NSUIHeartBeat _heartBeatThread:] + 324
4   com.apple.Foundation           	0x9295f194 forkThreadForFunction + 108
5   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 8:
0   libSystem.B.dylib              	0x9002bbc8 semaphore_wait_signal_trap + 8
1   libSystem.B.dylib              	0x900306ac pthread_cond_wait + 480
2   com.apple.ColorSync            	0x9159c224 pthreadSemaphoreWait(t_pthreadSemaphore*) + 56
3   com.apple.ColorSync            	0x9159b4c0 CMMConvTask(void*) + 40
4   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 9:
0   libSystem.B.dylib              	0x9000ab48 mach_msg_trap + 8
1   libSystem.B.dylib              	0x9000aa9c mach_msg + 60
2   com.apple.CoreFoundation       	0x907dcb78 __CFRunLoopRun + 832
3   com.apple.CoreFoundation       	0x907dc47c CFRunLoopRunSpecific + 268
4   com.apple.Foundation           	0x9296e164 -[NSRunLoop runMode:beforeDate:] + 172
5   com.apple.Foundation           	0x9296e09c -[NSRunLoop run] + 76
6   com.apple.Safari               	0x0003d5f0 0x1000 + 247280
7   com.apple.Foundation           	0x9295f194 forkThreadForFunction + 108
8   libSystem.B.dylib              	0x9002b508 _pthread_body + 96

Thread 0 crashed with PPC Thread State 64:
  srr0: 0x00000000001761d8 srr1: 0x000000000200f030                        vrsave: 0x0000000000000000
    cr: 0x44028422          xer: 0x0000000020000004   lr: 0x00000000001761d8  ctr: 0x00000000001761a0
    r0: 0x0000000000000000   r1: 0x00000000bfffe530   r2: 0x0000000002095000   r3: 0x0000000000000000
    r4: 0x0000000000001cc0   r5: 0x0000000000000003   r6: 0x00000000ffffffff   r7: 0x000000000c3f7000
    r8: 0x0000000000017180   r9: 0x000000000208d018  r10: 0x0000000000174dfc  r11: 0x000000000152ab98
   r12: 0x00000000001761a0  r13: 0x0000000000000000  r14: 0x0000000000000001  r15: 0x0000000000000001
   r16: 0x0000000000000000  r17: 0x0000000000000000  r18: 0x000000000001d34f  r19: 0x0000000000000000
   r20: 0x000000001d1432bd  r21: 0x00000000f3f2d025  r22: 0x0000000000000001  r23: 0x0000000002114560
   r24: 0x00000000bfffe728  r25: 0x000000000a16ba00  r26: 0x00000000001becd8  r27: 0x0000000000000730
   r28: 0x000000000af1a000  r29: 0x000000000a3f22a0  r30: 0x0000000000730063  r31: 0x00000000001761b0

[David Kilzer (:ddkilzer)]

Thanks for the bug report, Donnie!  I see this happened on WebKit nightly build r19919.  Do you have steps to reproduce it that work every time?  That will be the fastest way to get the issue fixed!

If this problem happens while you're browsing (but you can't reproduce it on demand), I would suggest using a newer WebKit nightly build to see if the issue still happens.

http://nightly.webkit.org/

[Mark Rowe (bdash)]

What is the connection between the crash report you included in your bug report and the topic of the bug which relates to poor performance due to disk activity?  As far as I can tell the two are completely unrelated.

[David Kilzer (:ddkilzer)]

Donnie, until we have specific steps to reproduce this performance issue, I'm going to change its priority to P2.

Note that if the performance issue is related to the number of bookmarks you have, you may need to share your bookmarks (~/Library/Safari/Bookmarks.plist) in order for someone else to reproduce this issue.

Also, when this happens, what are the top CPU-using processes in the Activity Monitor's window?  (Open up "Activity Monitor" from the /Applications/Utilities folder, hit Cmd-1 to open the activity window, then click on the "% CPU" column to sort by CPU usage.)

[Mark Rowe (bdash)]

And Donnie, can you *please* stop replying to the automated Bugzilla emails.  Add your comments to the bug via the web interface.

[Jonas Walldén]

I don't know if this is what the original reporter had in mind, but here goes...

I normally leave Safari running for many days or even weeks between restarts, and almost every time shortly after a relaunch I get excessive disk accesses for a few minutes which renders the application almost completely unresponsive. I've looked at it in gdb and it's the expiration process for the disk cache that deletes a lot of files.

Cleaning the cache is of course a good thing, but preferably it should be handled incrementally without postponing everything until the next launch.

My observations have been made with the release version (currently 2.0.4) since I'm not running nightlies for any longer periods of time.

[David Kilzer (:ddkilzer)]

(In reply to comment #5)
> I normally leave Safari running for many days or even weeks between restarts,
> and almost every time shortly after a relaunch I get excessive disk accesses
> for a few minutes which renders the application almost completely unresponsive.
> I've looked at it in gdb and it's the expiration process for the disk cache
> that deletes a lot of files.
> 
> Cleaning the cache is of course a good thing, but preferably it should be
> handled incrementally without postponing everything until the next launch.

This mechanism has been rewritten with the WebKit nightly builds.  It would be good to test using WebKit instead of Safari for the same amount of time to see if you experience the same issues.  (You should not--please file a bug if you do!)

[Mark Rowe (bdash)]

(In reply to comment #6)
> (In reply to comment #5)
> > I normally leave Safari running for many days or even weeks between restarts,
> > and almost every time shortly after a relaunch I get excessive disk accesses
> > for a few minutes which renders the application almost completely unresponsive.
> > I've looked at it in gdb and it's the expiration process for the disk cache
> > that deletes a lot of files.
> 
> This mechanism has been rewritten with the WebKit nightly builds.  It would be
> good to test using WebKit instead of Safari for the same amount of time to see
> if you experience the same issues.  (You should not--please file a bug if you
> do!)

The *disk cache* is not part of WebKit, it is down in the Foundation layer.  The in-memory cache in WebCore has been reworked recently, but we obviously haven't changed the disk cache behaviour from WebKit.  My understanding of the way the Foundation disk cache works is that it does expire resources incrementally so the behaviour described would be a bug.  It'd be handy if you could provide `sample' output from when Safari is hanging so we can see what is going on.

[David Kilzer (:ddkilzer)]

(In reply to comment #7)
> The *disk cache* is not part of WebKit, it is down in the Foundation layer. 
> The in-memory cache in WebCore has been reworked recently, but we obviously
> haven't changed the disk cache behaviour from WebKit.  [...]

Sorry, my bad.  I only work here.  :)

[Jonas Walldén]

(In reply to comment #7)
> It'd be handy if you could provide `sample' output from when Safari is hanging
> so we can see what is going on.

Yep, will try to catch this next time. Donnie, if my earlier comment doesn't match your problem I'd be happy to start a new ticket instead of hijacking this one.

[Jonas Walldén]

I've been running a WebKit nightly for 4-5 weeks without restarting it. I've used it heavily and have seen VSIZE balloon up to 2+ gigs at times but later it always returned to a few hundred megs so memory consumption hasn't been a big issue.

Now, today I restarted WebKit while having tools such as gdb, sample and fs_usage ready to monitor the behavior. At first the restarted process behaved nicely; I had no problem surfing to a web site and there was only minimal background I/O (I'm guessing caused by [NSURLCache _diskCacheCreateLRUList:]).

However, one or two minutes after launch the cache cleaning started and the browser became mostly unusable. I could still create new tabs, switch among windows, open the Preferences window and so on, but any request for a URL would get a progress bar pinned at ~5% and then block. Even Help > Installed Plug-Ins (which loads a local HTML file) would block.

This state persisted for over 10 minutes. Safari consumed 5-10% CPU and I was able to grab backtraces and other stats using the tools I mentioned earlier. Please see the attached file for details. [NSURLCache _diskCacheSync] looks like a prime suspect if it uses a global lock.

[Jonas Walldén]

Created attachment 15083 [details]
Logs from gdb, sample and fs_usage

[David Kilzer (:ddkilzer)]

Jonas, I'm curious as to how big your cache is.  Could you run these commands and report the results?

$ du -sk ~/Library/Caches/Safari
$ find ~/Library/Caches/Safari -type f  | wc -l

[Jonas Walldén]

$ du -sk ~/Library/Caches/Safari
23172   /Users/jonasw/Library/Caches/Safari
$ find ~/Library/Caches/Safari -type f | wc -l
    1970

I guess this doesn't say anything about how big the cache was before the relaunch and the subsequent cleaning. Maybe I should wait another 4-5 weeks first. :-)

I'm also a bit curious about all the "mds" entries in the fs_usage report. Since Spotlight by default doesn't index e.g. /usr/include/ I've manually added my volume root with mdimport. Perhaps this impacts the speed of deleting large number of cache files? Doesn't explain the lack of incremental cleaning, though.

[David Kilzer (:ddkilzer)]

(In reply to comment #13)
> I guess this doesn't say anything about how big the cache was before the
> relaunch and the subsequent cleaning. Maybe I should wait another 4-5 weeks
> first. :-)

And before you test, you should make a copy of ~/Library/Caches/Safari so you may (more easily) recreate the issue!

> I'm also a bit curious about all the "mds" entries in the fs_usage report.
> Since Spotlight by default doesn't index e.g. /usr/include/ I've manually added
> my volume root with mdimport. Perhaps this impacts the speed of deleting large
> number of cache files? Doesn't explain the lack of incremental cleaning,
> though.

Was Spotlight re-indexing your hard drive when you were doing this?  Or perhaps it was being triggered to re-index when the cache was being pruned since you added the volume root?  (I haven't looked at the attached log files yet; not sure I would know what to look for anyway.)

[Dave Hyatt]

(In reply to comment #10)
> I've been running a WebKit nightly for 4-5 weeks without restarting it. I've
> used it heavily and have seen VSIZE balloon up to 2+ gigs at times but later it
> always returned to a few hundred megs so memory consumption hasn't been a big
> issue.
> 
> Now, today I restarted WebKit while having tools such as gdb, sample and
> fs_usage ready to monitor the behavior. At first the restarted process behaved
> nicely; I had no problem surfing to a web site and there was only minimal
> background I/O (I'm guessing caused by [NSURLCache _diskCacheCreateLRUList:]).
> 
> However, one or two minutes after launch the cache cleaning started and the
> browser became mostly unusable. I could still create new tabs, switch among
> windows, open the Preferences window and so on, but any request for a URL would
> get a progress bar pinned at ~5% and then block. Even Help > Installed Plug-Ins
> (which loads a local HTML file) would block.
> 
> This state persisted for over 10 minutes. Safari consumed 5-10% CPU and I was
> able to grab backtraces and other stats using the tools I mentioned earlier.
> Please see the attached file for details. [NSURLCache _diskCacheSync] looks
> like a prime suspect if it uses a global lock.
> 

I've been seeing nearly identical behavior on Windows Vista with Safari 3.  I strongly suspect the disk cache, but I've been unable to get it to reproduce reliably enough to trap it in the debugger.

[Jonas Walldén]

(In reply to comment #14)
> And before you test, you should make a copy of ~/Library/Caches/Safari so you
> may (more easily) recreate the issue!

Good idea.

> Was Spotlight re-indexing your hard drive when you were doing this?  Or perhaps
> it was being triggered to re-index when the cache was being pruned since you
> added the volume root?  (I haven't looked at the attached log files yet; not
> sure I would know what to look for anyway.)

My Spotlight tweak was made last year so it wasn't indexing anything that I know of at this time, but if it monitors all low-level file ops it should at least be queueing deleted paths for later processing. I doubt it contributed significantly to the problem.

By the way, I've got ~/Library/Caches/WebKit/ as well. Isn't that the one we're really interested in here since I'm running a nightly? (It's size and file count is even smaller than my previous numbers.) The date stamps in there are from today while everything in ~/Library/Caches/Safari/ is at least 30 days old.

[Mark Rowe (bdash)]

One thing to note is that Safari on Windows and Tiger use very different disk cache implementations.  Tiger uses an implementation in Foundation, while Windows uses one in CFNetwork.  If they are at fault, Bugzilla is not the right place to track the issue so a Radar would need to be filed.

[donnie]

(In reply to comment #16)
> (In reply to comment #14)
> > And before you test, you should make a copy of ~/Library/Caches/Safari so you
> > may (more easily) recreate the issue!
> 
> Good idea.
> 
> > Was Spotlight re-indexing your hard drive when you were doing this?  Or perhaps
> > it was being triggered to re-index when the cache was being pruned since you
> > added the volume root?  (I haven't looked at the attached log files yet; not
> > sure I would know what to look for anyway.)
> 
> My Spotlight tweak was made last year so it wasn't indexing anything that I
> know of at this time, but if it monitors all low-level file ops it should at
> least be queueing deleted paths for later processing. I doubt it contributed
> significantly to the problem.
> 
> By the way, I've got ~/Library/Caches/WebKit/ as well. Isn't that the one we're
> really interested in here since I'm running a nightly? (It's size and file
> count is even smaller than my previous numbers.) The date stamps in there are
> from today while everything in ~/Library/Caches/Safari/ is at least 30 days
> old.
> 

I am the originator of this thread. I have a workable solution. I set all the following folders in Users/Library/Caches to NO ACCESS: Metadata, Safari and WebKit. They all now have a red circle with a minus sign through it. Works like a charm. It's a very serious bug with the disc caching in Safari. Slows your CPU down to a crawl. Also very difficult to reproduce and trace. But the above procedure stops the activity cold. Took me months to figure out. But finally won the battle! Sorry for the delay in posting a solution. I was told not to reply to any e-mails sent from [e-mail]. So I'm posting my findings here today. Best wishes for everyone. Happy Fathers Day to you Dads out there! Peace and Love. Donnie Dixon 

[Mark Rowe (bdash)]

Closing the bug because you have hacked a workaround locally is hardly productive.  We still need to track down the root cause of this issue so that it can be fixed in the appropriate component.

[donnie]

(In reply to comment #19)
> Closing the bug because you have hacked a workaround locally is hardly
> productive.  We still need to track down the root cause of this issue so that
> it can be fixed in the appropriate component.
> 

Whatever you feel is best to do, please by all means do that. I had a serious problem with the app. Tried everything. Asked many questions. No Answers. Received no definite solutions. Tried to solve the problem by myself. Yes. That might not be politically correct way to solve the issue. But it worked for me. Hope that you and the WebKit Team can come up with an honest solution. Best wishes. Donnie Dixon

[Ahmad Saleem]

@ap - It seems to be for old macOS and PowerPC eroa, I don't think it would be applicable anymore and Safari itself has evolved and Hardware as well (e.g., SSD, NVME drives), so I think it might not be applicable anymore. Do you think we need to keep this open?

[Alexey Proskuryakov]

Indeed, so many things have changes since 2007, and currently we aren't seeing any reports of this behavior.