Stefan, it looks like we're working along the same lines - more of which later.
Although I could re-open the bugzilla report the problem is, the first question asked is "does this affect the latest version?" and the answer is "NO" - not since 2.6.25-rc9 that I know about, and possibly earlier. With that I doubt there will be much interest in solving this since it'll be a case of "use the latest kernel". I'd like to get a bit further in understanding the issue first. I've attached a git-diff patch "ec_debug ACPI EC delayed printk() messaging" against the current ubuntu-hardy HEAD (commit 135a18b9c37be8...). It introduces buffered printk() messages via calls to ec_debug(const char *func, const char *format, args...). It allows us to add as many debug messages as we want without affecting the timing because they are sent to the console immediately. It collects the messages in the buffer and auto-flushes if it gets full and more importantly, immediately after the 2 known code-points when the EC either succeeds or fails. The resulting /var/log/dmesg entries need a bit of manual fix-up since the messages are out of time-sequence and have the time-of-printing prefixed too. It is pretty simple to use an editor to tidy it up and put the messages back in sequence though. Here's an example of a successful boot with 2.6.24.3 (manually built ubuntu-hardy tree). I wish there was an easy way to capture a failed boot, but non of the Vaio's have serial ports so we can't capture via a serial console. My usual method is to aim the DV-camcorder at the screen and record the output - I'll try that method later today. It seems to show that the init_subsys for acpi_init() and acpi_scan_init() are overlapping. I need to add additional messages to determine which subsys is responsible for the call to acpi_boot_ec_enable(). I'll try to make progress later today and report back. In the meantime, the attached patch is available if you want to drop in your own debug tracing messages to chase down other possibilities. [ 23.109039] ACPI: bus type pci registered [ 23.109168] PCI: Using configuration type 1 [ 23.110342] ACPI: acpi_ec_ecdt_probe() [ 23.110345] ACPI: EC: Look up EC in DSDT [ 23.117192] ACPI: Interpreter enabled [ 23.117254] ACPI: (supports S0 S3 S4 S5) [ 23.117510] ACPI: Using IOAPIC for interrupt routing [ 23.117676] ACPI: acpi_boot_ec_enable() [ 23.117677] ACPI: ec_install_handlers(<ec>) [ 23.117713] ACPI: acpi_ec_space_handler(<args...>) [ 23.117714] ACPI: acpi_ec_read(<ec>, <addres>, <data>) [ 23.117715] ACPI: acpi_ec_transaction(<ec>, 128, <wdata>, 1, <rdata>, 1, 0) [ 23.117717] ACPI: acpi_ec_wait(<ec>, 2, 0) [ 23.117718] ACPI: acpi_ec_wait() else [ 23.117720] ACPI: acpi_ec_transaction_unlocked(<ec>, 128, <wdata>, 1, <rdata>, 1, 0) [ 23.117723] ACPI: acpi_ec_wait(<ec>, 2, 0) [ 23.117724] ACPI: acpi_ec_wait() else [ 23.117940] ACPI: acpi_ec_wait(<ec>, 1, 0) [ 23.117941] ACPI: acpi_ec_wait() else [ 23.117999] ACPI: acpi_ec_gpe_handler(<data>) [ 23.118002] ACPI: EC: non-query interrupt received, switching to interrupt mode [ 23.118310] ACPI: acpi_ec_gpe_handler(<data>) [ 23.118322] ACPI: acpi_ec_space_handler(<args...>) [ 23.118323] ACPI: acpi_ec_read(<ec>, <addres>, <data>) [ 23.118324] ACPI: acpi_ec_transaction(<ec>, 128, <wdata>, 1, <rdata>, 1, 0) [ 23.118325] ACPI: PCI Root Bridge [PCI0] (0000:00) [ 23.140534] ACPI: EC: GPE = 0x17, I/O: command/status = 0x66, data = 0x62 [ 23.140598] ACPI: EC: driver started in interrupt mode My analysis of the call paths: init/main.c::start_kernel() init/main.c::rest_init() init/main.c::kernel_init() init/main.c::do_basic_setup() init/main.c::do_initcalls() initcall_t *call; for (call = __initcall_start; call < __initcall_end; call++) { $ objdump -t builds/ubuntu-hardy/vmlinux | egrep '__initcall_(acpi_init|acpi_scan_init|acpi_ec_init)' ffffffff80624dc8 l O .initcall.init 0000000000000008 __initcall_acpi_init4 ffffffff80624dd0 l O .initcall.init 0000000000000008 __initcall_acpi_scan_init4 ffffffff80624dd8 l O .initcall.init 0000000000000008 __initcall_acpi_ec_init4 drivers/acpi/bus.c::acpi_init() drivers/acpi/bus.c::acpi_bus_init() drivers/acpi/ec.c::acpi_ec_ecdt_probe() drivers/acpi/ec.c::make_acpi_ec() drivers/acpi/tables/tbxface.c::acpi_get_table() drivers/acpi/ec.c::ec_install_handlers() if (ec->handlers_installed) return 0; drivers/acpi/events/evxface.c::acpi_install_gpe_handler() drivers/acpi/events/evxfevnt.c::acpi_set_gpe_type() drivers/acpi/events/evxfevnt.c::acpi_enable_gpe() drivers/acpi/events/evgpe.c::acpi_ev_enable_gpe() drivers/acpi/hardware/hwgpe.c::acpi_hw_write_gpe_enable_reg() drivers/acpi/events/evxfregn.c::acpi_install_address_space_handler() ec->handlers_installed = 1; } } } } subsys_initcall(acpi_init) drivers/acpi/scan.c::acpi_scan_init() drivers/acpi/ec.c::acpi_boot_ec_enable() if (!boot_ec || boot_ec->handlers_installed) return 0; drivers/acpi/ec.c::ec_install_handlers() if (ec->handlers_installed) return 0; drivers/acpi/events/evxface.c::acpi_install_gpe_handler() drivers/acpi/events/evxfevnt.c::acpi_set_gpe_type() drivers/acpi/events/evxfevnt.c::acpi_enable_gpe() drivers/acpi/events/evxfregn.c::acpi_install_address_space_handler() ec->handlers_installed = 1; } } } subsys_initcall(acpi_scan_init) drivers/acpi/ec.c::acpi_ec_init() proc_mkdir() drivers/acpi/scan.c::acpi_bus_register_driver() } subsys_initcall(acpi_ec_init) I've been thinking there's a clue in the log output when it fails: ACPI: EC: acpi_ec_wait timeout, status=0, expect_event=1 // event 1 = ACPI_EC_EVENT_OBF_1 = output buffer full ACPI: EC: read timeout, command=128 // 128 = 0x80 = ACPI_EC_COMMAND_READ To deliver those messages the code path is: drivers/acpi/ec.c::acpi_ec_transaction(ec, ACPI_EC_COMMAND_READ,...) drivers/acpi/ec.c::acpi_ec_transaction_unlocked(ec, ACPI_EC_COMMAND_READ, ...) drivers/acpi/ec.c::acpi_ec_wait(ec, ACPI_EC_EVENT_OBF_1, ...) if (likely(test_bit(EC_FLAGS_GPE_MODE, &ec->flags)) && likely(!force_poll)) { if (wait_event_timeout(ec->wait, acpi_ec_check_status(ec, event), msecs_to_jiffies(ACPI_EC_DELAY))) goto end; pr_err(PREFIX "acpi_ec_wait timeout," " status = %d, expect_event = %d\n", acpi_ec_read_status(ec), event); end: } pr_err(PREFIX "read timeout, command = %d\n", command); } } There are two ways to that code-path: drivers/acpi/ec.c::acpi_ec_read(ec, ...) drivers/acpi/ec.c::ec_transaction(ec, command, ...) // EXPORTed acpi_ec_read() is called from two functions: drivers/acpi/ec.c::ec_read() // EXPORTed drivers/acpi/ec.c::acpi_ec_space_handler() ec_read() is called from: drivers/acpi/sbshc.c::smb_hc_read() // SMBus controller acpi_ec_space_handler() is called from: drivers/acpi/ec.c::ec_install_handlers() ec_transaction(), although EXPORTed, doesn't seem to be used by anything currently. ** Attachment added: "ec_debug ACPI EC delayed printk() messaging" http://launchpadlibrarian.net/15943102/ec_debug.patch -- [Hardy] ACPI Embedded Controller (EC) stops boot when kernel boot 'quiet' option is enabled or AC power is connected https://bugs.launchpad.net/bugs/191137 You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs