Mavericks sleep/hibernate causes high fan activity

Question

After updating to OS X 10.9, my 13-inch, Late 2011 MacBook Pro runs into trouble when going to sleep. About a minute after going to sleep, the fan suddenly starts running high, and keeps up doing so for about another minute (but that time is highly variable).

There are no other associated problems, I can wake the computer from sleep without problems. However, this activity is concerning. First of all, the computer gets extremely hot during that time (hence, I think, the fan activity), and of course the sleep process is quite delayed.

I’ve noticed some weird log entries in my Console:

21/12/2013 12:07:11.000 kernel[0]: PM notification timeout (pid 48014, Messages)
21/12/2013 12:07:15.000 kernel[0]: AirPort_Brcm43xx::powerChange: System Sleep 
21/12/2013 12:07:18.000 kernel[0]: hibernate image path: /var/vm/sleepimage
21/12/2013 12:07:18.000 kernel[0]: efi pagecount 43
21/12/2013 12:07:18.000 kernel[0]: hibernate_page_list_setall(preflight 1) start 0xffffff80f5dbe000, 0xffffff80f603e000
21/12/2013 12:07:18.000 kernel[0]: hibernate_page_list_setall time: 224 ms
21/12/2013 12:07:18.000 kernel[0]: pages 1960650, wire 456636, act 439481, inact 53144, cleaned 0 spec 48, zf 199674, throt 0, compr 693907, xpmapped 8652081
21/12/2013 12:07:18.000 kernel[0]: could discard act 6855 inact 76195 purgeable 18521 spec 16142 cleaned 47
21/12/2013 12:07:18.000 kernel[0]: hibernate_page_list_setall preflight pageCount 1842890 est comp 66 setfile 5267647972 min 4294967296
…
21/12/2013 12:07:20.000 kernel[0]: [0x1a5aeab000, 0x1000]
21/12/2013 12:07:20.000 kernel[0]: [0x1a5aeb9000, 0x7000]
21/12/2013 12:07:20.000 kernel[0]: [0x1a5aec3000, 0x1000]
…
21/12/2013 12:07:21.000 kernel[0]: [0x5a7a6f000, 0x39000]
21/12/2013 12:07:21.000 kernel[0]: *** kernel exceeded 500 log message per second limit  -  remaining messages this second discarded ***
21/12/2013 12:10:19.000 kernel[0]: hibernate_page_list_setall(preflight 0) start 0xffffff80f5dbe000, 0xffffff80f603e000
21/12/2013 12:10:19.000 kernel[0]: hibernate_page_list_setall time: 281 ms
21/12/2013 12:10:19.000 kernel[0]: pages 1961557, wire 456989, act 439956, inact 53160, cleaned 0 spec 120, zf 199606, throt 0, compr 693907, xpmapped 8708503
21/12/2013 12:10:19.000 kernel[0]: could discard act 6855 inact 76248 purgeable 18521 spec 16148 cleaned 47
21/12/2013 12:10:19.000 kernel[0]: hibernate_page_list_setall found pageCount 1843738
21/12/2013 12:10:19.000 kernel[0]: IOHibernatePollerOpen, ml_get_interrupts_enabled 0
21/12/2013 12:10:19.000 kernel[0]: IOHibernatePollerOpen(0)
21/12/2013 12:10:19.000 kernel[0]: encryptStart a44a0
21/12/2013 12:10:19.000 kernel[0]: bitmap_size 0x3f5a4, previewSize 0x359ac8, writing 1842596 pages @ 0x43d50c
21/12/2013 12:10:19.000 kernel[0]: encryptEnd 19175c00
21/12/2013 12:10:19.000 kernel[0]: image1Size 0x24c5b000, encryptStart1 0xa44a0, End1 0x19175c00
21/12/2013 12:10:19.000 kernel[0]: encryptStart 24c5b000
21/12/2013 12:10:19.000 kernel[0]: encryptEnd 11c0c5e00
21/12/2013 12:10:19.000 kernel[0]: PMStats: Hibernate write took 175406 ms
21/12/2013 12:10:19.000 kernel[0]: all time: 175406 ms, comp bytes: 7547641856 time: 6109 ms 1178 Mb/s, crypt bytes: 4568892768 time: 7119 ms 612 Mb/s, 
21/12/2013 12:10:19.000 kernel[0]: image 4765540352 (90%), uncompressed 7547641856 (794110), compressed 4749442640 (62%), sum1 4b91d7ac, sum2 a6e4a967
21/12/2013 12:10:19.000 kernel[0]: zeroPageCount 87345, wiredPagesEncrypted 337128, wiredPagesClear 118809, dirtyPagesEncrypted 1386749
21/12/2013 12:10:19.000 kernel[0]: hibernate_write_image done(0)
21/12/2013 12:10:19.000 kernel[0]: sleep

– After (what I’m assuming is) the normal hibernation initiation, the kernel goes crazy and spews memory addresses (?!) into the log. This only goes on for a few seconds, and the hibernate write itself takes 175406 ms ≈ 3 min (I’ve got 8 GB of RAM).

What do these log entries mean? Do they hold any clue to solve this problem?

Other people seem to have the same problem but there’s no definitive solution. The article seems to indicate that the computer shouldn’t hibernate immediately but much later, but it makes no mention at all of the weird addresses in the log.

Answer 1

For whatever reason the kernel is encrypting the hibernation file and it's safe to assume that the encryption, as a CPU-intensive process, is causing the heating up. The Hibernation File, sometimes referred to as the 'sleepimage'-file, is usually the same size as your RAM and can sometimes get corrupted.

I would recommend checking your Powermanagement-Settings within the Terminal by using the folowing command:

pmset -g

You should get a list of the urrent settings which you can interpret by typing 'man pmset' or by looking at the Docs provided by Apple here. Please check it the Setting for 'hibernatemode' is anything other than 3 (for Mac portables). Perhaps you can post the complete Settings.

I would suggest you try to delete the sleepimage in case it is corrupted (even though i don't see any errors). You can do it within the Terminal with this command:

sudo rm /private/var/vm/sleepimage

It will be recreated the next time your Mac goes into sleep-mode. Does the encryption still occur with the new sleepimage?

Answer 2

My macbook does the same. I think this is intended behaviour because it tries to quickly cool itself down, because you might put it in a backpack and then it would be harder for the laptop to cool. So it does a quick cooldown procedure.

This is only a guess though.