Disabled microcode.ctl init script and launched it manually after boot, no errors. Hmm.
Will investigate some more whether there were init script errors during normal microcode bootup and what they were.

I remember that the microcode.ctl init script error messages that occurred _sometimes_ were that it's not able to locate the firmware files. Couldn't get this error during the last couple boots though.
This firmware file spottiness might be the reason for the resume lockup, since perhaps it couldn't locate the files during the restricted environment during resume and doesn't handle the resulting error condition properly (reloading firmware on resume once was a problem for my formerly popular acx100 driver, too, thus I figure that this might be the reason here).

BTW, bootup dmesg is:

[   33.499119] platform microcode: firmware: requesting intel-ucode/06-1c-02
[   33.549317] platform microcode: firmware: requesting intel-ucode/06-1c-02
[   33.579665] Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Pet
er Oruba
[   33.813420] ppdev: user-space parallel port driver
[   33.882721] microcode: CPU0 updated from revision 0x208 to 0x20a, date = 2008
-06-04 
[   33.892541] microcode: CPU1 updated from revision 0x208 to 0x20a, date = 2008-06-04 

hmm, normally the firmware is loaded only once upon system bootup (or when a cpu goes down/up -- not down_frozen with suspend). The result is cached (either an appropriate ucode file or the fact that it's not available) so that it doesn't need to be reloaded upon system suspend/resume. IOW., the load-firmware path is not supposed to be taken in this case.. and in any case it does check error cases.
I'll review it all again.

More comments:
obviously this is an Atom CPU in my case (probably doesn't matter, but anyway).
It's not the firmware loading which matters, it's purely whether microcode.ko remains loaded before suspend, I believe. Hmm, OTOH I need to check the "DON'T load firmware script on bootup but DO load firmware.ko (manually)" case whether that one breaks resume, too, or only in case we did upload an Intel firmware...
Thanks a lot!

Tried it: disabled init script, removed pm-utils SUSPEND_MODULES part, rebooted.
--> no microcode.ko loaded, manually loaded it, pm-suspend, WORKED. Retried pm-suspend, worked. Manually launched init script (dmesg now showed additional lines detailling microcode version updates), pm-suspend, DEAD.
IOW it's some "microcode image handling" part of microcode.ko which causes lockup upon resume, not the microcode.ko module's basic handling itself.

sorry for the late reply.

do you have a firmware file for microcode or/and .dat file (e.g. /etc/microcode.dat by default)? The microcode init script (if that's the 'microcode_ctl' package) seems to use the later one.

Upon loading, microcode.ko tries to load a desired firmware file, as the message from one of your posts suggests "requesting intel-ucode/06-1c-02"... then we see 
"microcode: CPU0 updated from revision 0x208 to 0x20a, date =
2008" perhaps suggesting that firmware was located (unless an update with mcrocode_ctl via /dev/cpu/microcode quickly followed...)

when does microcode.ko get loaded? Is it done by the same startup script that runs mirocode_ctl?

I'll try to reproduce it (although, in my case I'll need to alter the logic to always load ucode, as my cpu seems to have the latest ucode by default). yeas, I've tried this scenario before code submission but who knows :-)

The relevant image file seems to be /usr/share/misc/intel-microcode.dat

microcode.ko seems to be requested directly by /etc/init.d/microcode_ctl itself:

# Lets just be sure we have a device file...
# ... with workaround because different name policy in lanana and devfsd
if [ -x /sbin/modprobe ] ; then
    /sbin/modprobe -q -k -s microcode > /dev/null 2> /dev/null || true
fi

and dmesg activity (including timestamps!) seems to fully indicate that module loading and update happens together, by the init script.

But this is pretty much highlevel reasoning, what should be done instead is something like yanking out microcode PM handling in its entirety and observe whether that fixes the lockup by not doing anything there, then re-add _parts_ of the handling until it locks up again, then add lots of debugging to the last-before-lockup configuration to detect what's acting up in the lockup case.
But, sadly, someone else will have to do this in the near future at least.

Thanks!

I don't have consistent hangs in my setup [*] (and see [**] remarks)

Do you have any scripts in /etc/pm/sleep.d/ (these that may run upon resuming) related to 'microcode_ctl'?

I wonder if anyone else with systems where 'microcode' is updated one way or another (/dev/cpu/microcode or via firmware) sees similar problems...

In any case, sorry for inconvenience :( 


[*] 'consistent', because I had 2 hangs in about 20 attempts, although only one of them was with 'microcode' being loaded. Moreover, all the time I see messages like these below upon resuming:

Message from syslogd@earth at Wed Dec 10 22:55:00 2008 ...
earth kernel: [ 5735.486241] Uhhuh. NMI received for unknown reason b0 on CPU 0.

Message from syslogd@earth at Wed Dec 10 22:55:00 2008 ...
earth kernel: [ 5735.486243] You have some hardware problem, likely on the PCI bus.

Message from syslogd@earth at Wed Dec 10 22:55:00 2008 ...
earth kernel: [ 5735.486245] Dazed and confused, but trying to continu

anyway, the log with microcode is as follows:

[**]
(built with "#define DEBUG" at the top of microcode_{core,intel}.c files to enable pr_debug() and additionally, the logic is slightly changed to load the 'current' microcode -- no newer versions for my cpu seem to be available)

(1) insmod microcode.ko

[ 3155.236312] microcode: CPU0 added
[ 3155.237699] microcode: collect_cpu_info : sig=0x6f2, pf=0x20, rev=0x57
[ 3155.237708] platform microcode: firmware: requesting intel-ucode/06-0f-02
[ 3155.273943] microcode: data file intel-ucode/06-0f-02 load failed
[ 3155.273949] microcode: CPU1 added
[ 3155.297778] microcode: collect_cpu_info : sig=0x6f2, pf=0x20, rev=0x57
[ 3155.297784] platform microcode: firmware: requesting intel-ucode/06-0f-02
[ 3155.303554] microcode: data file intel-ucode/06-0f-02 load failed
[ 3155.303565] Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba

(2) microcode_ctl -f ./microcode-20080401.dat

[ 5682.272488] microcode: CPU0 found a matching microcode update with version 0x57 (curren
[ 5682.272828] microcode: CPU0 updated from revision 0x57 to 0x57, date = 2007-03-15
[ 5682.279724] microcode: CPU1 found a matching microcode update with version 0x57 (curren
[ 5682.279958] microcode: CPU1 updated from revision 0x57 to 0x57, date = 2007-03-15

(3) and now suspend/resume -- 'cached' versions are applied for both cpus.

[ 5730.951311] Disabling non-boot CPUs ...
[ 5730.951398] microcode: CPU1 removed
[ 5730.953943] CPU 1 is now offline
[ ... ]
[ 5731.038200] CPU1 is down
[ 5731.038390] Extended CMOS year: 2000
[ 5731.038390] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[ 5731.038390] Back to C!

[ 5731.038390] microcode: CPU0 resumed
[ 5731.038390] microcode: collect_cpu_info : sig=0x6f2, pf=0x20, rev=0x57
[ 5731.038390] microcode: CPU0 updated from revision 0x57 to 0x57, date = 2007-03-15
[ 5731.038390] Extended CMOS year: 2000
[ 5731.038390] Enabling non-boot CPUs ...
[ ... ]
[ 5731.208040] microcode: CPU1 resumed
[ 5731.208043] microcode: collect_cpu_info : sig=0x6f2, pf=0x20, rev=0x57
[ 5731.208291] microcode: CPU1 updated from revision 0x57 to 0x57, date = 2007-03-15 
[ 5731.208294] microcode: CPU1 added
[ 5731.209282] CPU1 is up

There seems to be at least _one_ recursive mutex_lock():

microcode_init_cpu() mutex_lock() -> microcode_update_cpu() -> microcode_resume_cpu() -> microcode_fini_cpu() mutex_lock()!!

Right?

I don't know, but I don't feel safe using microcode_lock for anything larger than the microcode_ops directly, because _also_ locking entire higher-level functions is exactly what usuallly gets one in boiling water...

I've added logging, but so far it seems to work mostly, possibly a timing issue here tweaked by printk delays (is the CPU online invocation of CPU1 asynchronous and thus firmware updating??).

One should definitely get this debugged before .28 is intended to be released in two weeks or so.

Handled-By : Dmitry Adamushko <dmitry.adamushko@gmail.com>

Yes, you are right about a possible deadlock with 'mutex_lock'. I somehow overlooked this case... will fix, thanks!

However, these paths are not common and would indicate a big problem somewhere else. Adding printk() to these 'if' blocks (right before microcode_fini_cpu() gets called) won't introduce any timing issues possibly helping to avoid a deadlock.

Not sure what do you mean by "is the CPU online invocation of CPU1
asynchronous and thus firmware updating??"... asynchronous wrt what code?

microcode update is always done in a process context (the one that's running cpu_up()) on a target cpu.

I actually see a hang on my macbook pro rev 1,1 too *on resume from s2ram* whenever I have updated the microcode of the core 1 duo before.

However I have also a script in /etc/pm to load the updated microcode again.

OK, I did some investigation, a couple notes:

Not all wrmsr in microcode_intel.c are being locked. This might be a problem.

mc_sysdev_resume() cpu 0 condition is not being assured fully properly (there should probably either be an if cpu == 0 or a WARN_ON cpu != 0).

The "microcode: CPU%d removed/added" messages are IDENTICALLY duplicated in various places. BAAAD. Lotsa fun during debugging.

Many symbols aren't properly marked static for local scope. (watch "nm -n" for capital letters).

Logical layering in the driver (and consequently, locking) seems a wee bit broken (first, the potential mutex_lock deadlock, and then there are some functions which are "internal" manipulations of "uci / valid" and should probably _not_ take the lock themselves, plus for some weird reason microcode_update_cpu() being called by mc_sysdev_resume() _without_ taking the lock!!).
Those to-be-internal functions should probably be named __func() or so.

Why is microcode_update_cpu() sometimes being called with set_cpus_allowed_ptr() and sometimes NOT?? Execution is best to be restricted to the currently executing CPU within this function itself, right?

Lots of questions... (but in case of legitimate, intentional code, some comments there would help I think)

About the deadlock: no useful idea where the problem is, and unfortunately I won't spend more time on this now since I've been spending too much time already. As for .28, I'm pondering whether even _COMPLETELY disabling_ firmware reload on resume would be the way to go, especially in light of the new report before my comment, and also since the driver seems to be in need of some structural updates in general to correct (some?) of the things above, IOW, .29 work probably.

Deadlocks seemed to occur mainly with no debug logging, and work mainly in case the driver did have debugging enabled.

Thanks a lot for your plentiful attention to this bug report so far!

Yes, the locking scheme might have been done cleaner. There were a number of other issues on my 'todo' list but I somehow never manged to get my hands on them again.

The previous version of this code had a mutex_lock/unlock() (and a bit different locking scheme) in mc_sysdev_resume() as well, however this function gets called (or at least 'was' the last time I looked at it) with a spinlock being held by the upper layer -- so the use of mutex is not ok there and it got removed.

Now, is it safe? The reasoning is that mc_sysdev_resume() is called by the cpu #0 and all other cpus are still down at this point -- that's why we can also call microcode_update_cpu(0) with an explicit 'cpu == 0'. Yes, at the very least , some comments should have been added, my fault).

Provided, the assumption concerning mc_sysdev_resume() is solid (heh, need to verify again and it's better to avoid relying on it in any case), there should be normally no need for any additional locking in arch-specific parts -- since all operations are run with 'microcode_mutex' being held.

The potential deadlock with 'microcode_mutex' is a must fix, of course.

>
> Thanks a lot for your plentiful attention to this bug report so far!
>

To be honest, due to some reasons I haven't really paid enough attention to this problem so far... but I'm going to do it now. So it's rather thanks a lot to you for your time and comments!

I'll try to come up with some more ideas.

Created attachment 19339 [details]
Fix a wrong use of microcode_mutex (debugging version)

Andreas,

I presume you have tried a version with that potential deadlock in microcode_fini_cpu() being fixed without any success?

If no, the (debugging version) fix is enclosed (in attachments' section).
If you or Soeren have a free minute, please give it a try :-)
(no need to enable pr_debug() output).

Moreover, according to Soeren, there is a microcode-related script in /etc/pm/ on his system. Do you also have it?

If so, could someone of you guys send it to me please? TIA.

p.s. I have yet another idea to verify... will do tomorrow.

Created attachment 19373 [details]
Fix a comparison && deadlock in microcode_resume_cpu()

I think I might have a logical explanation why it might hang upon resuming, OTOH it should have likely hanged each and every time.

(1) possible deadlock in microcode_resume_cpu() if either 'if' section is taken;

(2) now, I don't see it in spec. and can't experimentally verify it (newer ucodes don't seem to be available for my Core2duo)... but logically-wise, I'd think that when read upon resuming, the 'microcode revision' (MSR 0x8B) should be back to its original one (we need to reload ucode anyway so it doesn't seem logical if a cpu doesn't drop the version)... if so, the comparison with memcmp() for the full 'struct cpu_signature' is wrong... and that's how one of the aforementioned 'if' sections might have been triggered - leading to a deadlock.

Obviously, in my tests I simulated loading/resuming with the ucode of the same version (just to see that the file is loaded/re-loaded upon resuming) so this issue has never popped up.

I'd appreciate if someone with an appropriate system might give a try to the 2nd patch (titled "fix a comparison && deadlock...").

Fixed by: http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=280a9ca5d0663b185ddc4443052076c29652a328

This also fixes the bug for me (ie. the s2ram regression I had - I s2ram'd about three times and it worked so far). Thanks!