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
