Open Radar

 
18-Sep-2009 04:34 PM Michael Ash:
Summary: 
Every so often, typically once every couple of days, my entire GUI locks up for about 30 seconds, becomes responsive for another couple of seconds, then locks up for another 30 seconds. After this has passed, all is normal. Applications continue to run in the background (for example, my iTunes music continues to play) but nothing changes on screen, not even the clock.

Steps to Reproduce:
I'm afraid I don't know how to reproduce it. It appears that it may be linked to activating Expose, but I am not 100% sure.

Expected Results:
N/A

Actual Results:
N/A

Regression:
This occurred under 10.6.0, possibly more frequently. I never saw it under 10.5.

Notes:
This is what showed up in my Console log from the latest occurrence, from roughly the time when the lock-up began:

9/18/09 4:29:09 PM	iCal[2824]	VTIMEZONE does not match System Time Zone (US/Eastern) for 20060115T120000 to 20080115T120000: (
    "interval: 2006-04-02 03:00:00 -0400, offset: -14400",
    "interval: 2006-10-29 01:00:00 -0500, offset: -18000",
    "interval: 2007-03-11 02:00:00 -0400, offset: -14400",
    "interval: 2007-11-04 01:00:00 -0500, offset: -18000"
) != (
    "interval: 2006-04-02 03:00:00 -0400, offset: -14400",
    "interval: 2006-10-29 01:00:00 -0500, offset: -18000",

    "interval: 2007-03-11 03:00:00 -0400, offset: -14400",
    "interval: 2007-11-04 01:00:00 -0500, offset: -18000"
)

BEGIN:VTIMEZONE
LAST-MODIFIED:20080518T133942Z
TZID:US/Eastern
BEGIN:DAYLIGHT
TZOFFSETFROM:+0000
DTSTART:20060402T070000
TZOFFSETTO:-0400
TZNAME:EDT
END:DAYLIGHT
BEGIN:STANDARD
TZOFFSETFROM:-0400
DTSTART:20061029T020000
TZOFFSETTO:-0500
TZNAME:EST
END:STANDARD
BEGIN:DAYLIGHT
TZOFFSETFROM:-0500
DTSTART:20070311T010000
TZOFFSETTO:-0400
TZNAME:EDT
END:DAYLIGHT
BEGIN:STANDARD
TZOFFSETFROM:-0400
DTSTART:20071104T020000
TZOFFSETTO:-0500
TZNAME:EST
END:STANDARD
END:VTIMEZONE
9/18/09 4:29:09 PM	iCal[2824]	VTIMEZONE does not match System Time Zone (US/Eastern) for 20050629T110000 to 20070629T110000: (
    "interval: 2006-04-02 03:00:00 -0400, offset: -14400",
    "interval: 2006-10-29 01:00:00 -0500, offset: -18000",
    "interval: 2007-03-11 02:00:00 -0400, offset: -14400"
) != (
    "interval: 2005-10-30 01:00:00 -0500, offset: -18000",
    "interval: 2006-04-02 03:00:00 -0400, offset: -14400",
    "interval: 2006-10-29 01:00:00 -0500, offset: -18000",
    "interval: 2007-03-11 03:00:00 -0400, offset: -14400"
)

BEGIN:VTIMEZONE
LAST-MODIFIED:20080518T133938Z
TZID:US/Eastern
BEGIN:DAYLIGHT
TZOFFSETFROM:+0000
DTSTART:20060402T070000
TZOFFSETTO:-0400
TZNAME:EDT
END:DAYLIGHT
BEGIN:STANDARD
TZOFFSETFROM:-0400
DTSTART:20061029T020000
TZOFFSETTO:-0500
TZNAME:EST
END:STANDARD
BEGIN:DAYLIGHT
TZOFFSETFROM:-0500
DTSTART:20070311T010000
TZOFFSETTO:-0400
TZNAME:EDT
END:DAYLIGHT
END:VTIMEZONE
9/18/09 4:29:10 PM	iCal[2824]	VTIMEZONE does not match System Time Zone (America/Chicago) for 20050324T130000 to 20070324T130000: (
    "interval: 2005-10-30 01:00:00 -0600, offset: -21600",
    "interval: 2006-04-02 02:00:00 -0500, offset: -18000",
    "interval: 2006-10-29 01:00:00 -0600, offset: -21600"
) != (
    "interval: 2005-04-03 03:00:00 -0500, offset: -18000",
    "interval: 2005-10-30 01:00:00 -0600, offset: -21600",
    "interval: 2006-04-02 03:00:00 -0500, offset: -18000",
    "interval: 2006-10-29 01:00:00 -0600, offset: -21600",
    "interval: 2007-03-11 03:00:00 -0500, offset: -18000"
)

BEGIN:VTIMEZONE
LAST-MODIFIED:20080518T133938Z
TZID:America/Chicago
BEGIN:STANDARD
TZOFFSETFROM:+0000
DTSTART:20051030T070000
TZOFFSETTO:-0600
TZNAME:CST
END:STANDARD
BEGIN:DAYLIGHT
TZOFFSETFROM:-0600
DTSTART:20060402T010000
TZOFFSETTO:-0500
TZNAME:CDT
END:DAYLIGHT
BEGIN:STANDARD
TZOFFSETFROM:-0500
DTSTART:20061029T020000
TZOFFSETTO:-0600
TZNAME:CST
END:STANDARD
END:VTIMEZONE

I don't have any idea if it's related or if such things have shown up in the Console previously.


'prof' was successfully uploaded

21-Sep-2009 04:49 PM Michael Ash:
It just happened to me again. This time, Time Machine is implicated (very loosely) in my system.log. Here's the relevant section of my log:

Sep 21 16:46:19 Fear com.apple.backupd[94647]: Copied 7353 files (103.6 MB) from volume Fear.
Sep 21 16:46:26 Fear com.apple.backupd[94647]: Starting post-backup thinning
Sep 21 16:47:38 Fear com.apple.backupd[94647]: Deleted backup /Volumes/Tardis/Backups.backupdb/Fear/2009-09-20-155310: 453.84 GB now available
Sep 21 16:47:38 Fear com.apple.backupd[94647]: Post-back up thinning complete: 1 expired backups removed
Sep 21 16:47:38 Fear com.apple.backupd[94647]: Backup completed successfully.

The freeze started at precisely 16:47:00 (the clock froze at that time) and resumed at exactly 16:47:20.

21-Sep-2009 08:21 PM Michael Ash:
Looks like all of the log spam I associated with the freezes in the past was just coincidence. This problem just happened to me again, and absolutely nothing was logged for over one minute before or after the event. Once again it was *exactly* 20 seconds. Although the title of the bug says 30 seconds, that was just an estimate; I consider it likely that it always freezes for exactly 20 seconds, as it has done so both of the times where I've actually been able to keep precise track.

29-Sep-2009 05:20 PM Michael Ash:
'Mac Pro.spx' was successfully uploaded

29-Sep-2009 05:22 PM Michael Ash:
'DiagnosticReports.zip' was successfully uploaded

30-Sep-2009 03:36 PM Michael Ash:
The requested logs are attached. I will try to grab a stackshot next time the problem occurs and will send that in as well. Thanks for your continued attention to this!


'logs.zip' was successfully uploaded

03-Oct-2009 10:36 AM Michael Ash:
What luck! Not five minutes after I enabled the stackshot stuff, the problem reoccurred. I'm attaching the stackshot files and the logs as requested. The freeze started at 10:32:32 (14:32:32 GMT) and ended at 10:32:52.


'stackshot-and-logs.zip' was successfully uploaded