Re: [PATCH 1/2] Add some basic resume trace facilities

Nigel Cunningham
2006-06-13T22:10:14Z

[-- Attachment #1.1: Type: text/plain, Size: 11611 bytes --]

Hi.

On Wednesday 14 June 2006 07:35, Linus Torvalds wrote:
> Considering that there isn't a lot of hw we can depend on during
> resume, this is about as good as it gets.
>
> Use "#include <linux/resume-trace.h>", and then sprinkle TRACE_RESUME(0)
> commands liberally over the driver that you're trying to figure out why
> and where it hangs. Expect to waste a _lot_ of time, but at least this
> gives you _some_ chance to actually debug it, instead of just staring at a
> dead machine.
>
> Signed-off-by: Linus Torvalds <torvalds@osdl.org>

s/On laptop per child/One bdi2000 per computer/? I'll give it a try.

Regards,

Nigel

> ---
>
> Not a lot of space in the RTC, but it's the only piece of hardware that is
> (a) reachable at all times, regardless of any other setup and (b) doesn't
> lose it state or have firmware reset the memory of at boot.
>
> Side note: you really don't want to do this unless you have an external
> time-source like NTP that resets the clock to the right value after the
> boot is done ;)
>
> diff --git a/arch/i386/kernel/vmlinux.lds.S
> b/arch/i386/kernel/vmlinux.lds.S index 8831303..509af98 100644
> --- a/arch/i386/kernel/vmlinux.lds.S
> +++ b/arch/i386/kernel/vmlinux.lds.S
> @@ -37,6 +37,13 @@ SECTIONS
>
> RODATA
>
> + . = ALIGN(4);
> + __tracedata_start = .;
> + .tracedata : AT(ADDR(.tracedata) - LOAD_OFFSET) {
> + *(.tracedata)
> + }
> + __tracedata_end = .;
> +
> /* writeable */
> .data : AT(ADDR(.data) - LOAD_OFFSET) { /* Data */
> *(.data)
> diff --git a/drivers/base/power/Makefile b/drivers/base/power/Makefile
> index c0219ad..adc4250 100644
> --- a/drivers/base/power/Makefile
> +++ b/drivers/base/power/Makefile
> @@ -1,5 +1,5 @@
> obj-y := shutdown.o
> -obj-$(CONFIG_PM) += main.o suspend.o resume.o runtime.o sysfs.o
> +obj-$(CONFIG_PM) += main.o suspend.o resume.o runtime.o sysfs.o trace.o
>
> ifeq ($(CONFIG_DEBUG_DRIVER),y)
> EXTRA_CFLAGS += -DDEBUG
> diff --git a/drivers/base/power/trace.c b/drivers/base/power/trace.c
> new file mode 100644
> index 0000000..bcc5f12
> --- /dev/null
> +++ b/drivers/base/power/trace.c
> @@ -0,0 +1,228 @@
> +/*
> + * drivers/base/power/trace.c
> + *
> + * Copyright (C) 2006 Linus Torvalds
> + *
> + * Trace facility for suspend/resume problems, when none of the
> + * devices may be working.
> + */
> +
> +#include <linux/resume-trace.h>
> +#include <linux/rtc.h>
> +
> +#include <asm/rtc.h>
> +
> +#include "power.h"
> +
> +/*
> + * Horrid, horrid, horrid.
> + *
> + * It turns out that the _only_ piece of hardware that actually
> + * keeps its value across a hard boot (and, more importantly, the
> + * POST init sequence) is literally the realtime clock.
> + *
> + * Never mind that an RTC chip has 114 bytes (and often a whole
> + * other bank of an additional 128 bytes) of nice SRAM that is
> + * _designed_ to keep data - the POST will clear it. So we literally
> + * can just use the few bytes of actual time data, which means that
> + * we're really limited.
> + *
> + * It means, for example, that we can't use the seconds at all
> + * (since the time between the hang and the boot might be more
> + * than a minute), and we'd better not depend on the low bits of
> + * the minutes either.
> + *
> + * There are the wday fields etc, but I wouldn't guarantee those
> + * are dependable either. And if the date isn't valid, either the
> + * hw or POST will do strange things.
> + *
> + * So we're left with:
> + * - year: 0-99
> + * - month: 0-11
> + * - day-of-month: 1-28
> + * - hour: 0-23
> + * - min: (0-30)*2
> + *
> + * Giving us a total range of 0-16128000 (0xf61800), ie less
> + * than 24 bits of actual data we can save across reboots.
> + *
> + * And if your box can't boot in less than three minutes,
> + * you're screwed.
> + *
> + * Now, almost 24 bits of data is pitifully small, so we need
> + * to be pretty dense if we want to use it for anything nice.
> + * What we do is that instead of saving off nice readable info,
> + * we save off _hashes_ of information that we can hopefully
> + * regenerate after the reboot.
> + *
> + * In particular, this means that we might be unlucky, and hit
> + * a case where we have a hash collision, and we end up not
> + * being able to tell for certain exactly which case happened.
> + * But that's hopefully unlikely.
> + *
> + * What we do is to take the bits we can fit, and split them
> + * into three parts (16*997*1009 = 16095568), and use the values
> + * for:
> + * - 0-15: user-settable
> + * - 0-996: file + line number
> + * - 0-1008: device
> + */
> +#define USERHASH (16)
> +#define FILEHASH (997)
> +#define DEVHASH (1009)
> +
> +#define DEVSEED (7919)
> +
> +static unsigned int dev_hash_value;
> +
> +static int set_magic_time(unsigned int user, unsigned int file, unsigned
> int device) +{
> + unsigned int n = user + USERHASH*(file + FILEHASH*device);
> +
> + // June 7th, 2006
> + static struct rtc_time time = {
> + .tm_sec = 0,
> + .tm_min = 0,
> + .tm_hour = 0,
> + .tm_mday = 7,
> + .tm_mon = 5, // June - counting from zero
> + .tm_year = 106,
> + .tm_wday = 3,
> + .tm_yday = 160,
> + .tm_isdst = 1
> + };
> +
> + time.tm_year = (n % 100);
> + n /= 100;
> + time.tm_mon = (n % 12);
> + n /= 12;
> + time.tm_mday = (n % 28) + 1;
> + n /= 28;
> + time.tm_hour = (n % 24);
> + n /= 24;
> + time.tm_min = (n % 20) * 3;
> + n /= 20;
> + set_rtc_time(&time);
> + return n ? -1 : 0;
> +}
> +
> +static unsigned int read_magic_time(void)
> +{
> + struct rtc_time time;
> + unsigned int val;
> +
> + get_rtc_time(&time);
> + printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
> + time.tm_hour, time.tm_min, time.tm_sec,
> + time.tm_mon, time.tm_mday, time.tm_year);
> + val = time.tm_year; /* 100 years */
> + if (val > 100)
> + val -= 100;
> + val += time.tm_mon * 100; /* 12 months */
> + val += (time.tm_mday-1) * 100 * 12; /* 28 month-days */
> + val += time.tm_hour * 100 * 12 * 28; /* 24 hours */
> + val += (time.tm_min / 3) * 100 * 12 * 28 * 24; /* 20 3-minute intervals
> */ + return val;
> +}
> +
> +/*
> + * This is just the sdbm hash function with a user-supplied
> + * seed and final size parameter.
> + */
> +static unsigned int hash_string(unsigned int seed, const char *data,
> unsigned int mod) +{
> + unsigned char c;
> + while ((c = *data++) != 0) {
> + seed = (seed << 16) + (seed << 6) - seed + c;
> + }
> + return seed % mod;
> +}
> +
> +void set_trace_device(struct device *dev)
> +{
> + dev_hash_value = hash_string(DEVSEED, dev->bus_id, DEVHASH);
> +}
> +
> +/*
> + * We could just take the "tracedata" index into the .tracedata
> + * section instead. Generating a hash of the data gives us a
> + * chance to work across kernel versions, and perhaps more
> + * importantly it also gives us valid/invalid check (ie we will
> + * likely not give totally bogus reports - if the hash matches,
> + * it's not any guarantee, but it's a high _likelihood_ that
> + * the match is valid).
> + */
> +void generate_resume_trace(void *tracedata, unsigned int user)
> +{
> + unsigned short lineno = *(unsigned short *)tracedata;
> + const char *file = *(const char **)(tracedata + 2);
> + unsigned int user_hash_value, file_hash_value;
> +
> + user_hash_value = user % USERHASH;
> + file_hash_value = hash_string(lineno, file, FILEHASH);
> + set_magic_time(user_hash_value, file_hash_value, dev_hash_value);
> +}
> +
> +extern char __tracedata_start, __tracedata_end;
> +static int show_file_hash(unsigned int value)
> +{
> + int match;
> + char *tracedata;
> +
> + match = 0;
> + for (tracedata = &__tracedata_start ; tracedata < &__tracedata_end ;
> tracedata += 6) { + unsigned short lineno = *(unsigned short *)tracedata;
> + const char *file = *(const char **)(tracedata + 2);
> + unsigned int hash = hash_string(lineno, file, FILEHASH);
> + if (hash != value)
> + continue;
> + printk(" hash matches %s:%u\n", file, lineno);
> + match++;
> + }
> + return match;
> +}
> +
> +static int show_dev_hash(unsigned int value)
> +{
> + int match = 0;
> + struct list_head * entry = dpm_active.prev;
> +
> + while (entry != &dpm_active) {
> + struct device * dev = to_device(entry);
> + unsigned int hash = hash_string(DEVSEED, dev->bus_id, DEVHASH);
> + if (hash == value) {
> + printk(" hash matches device %s\n", dev->bus_id);
> + match++;
> + }
> + entry = entry->prev;
> + }
> + return match;
> +}
> +
> +static unsigned int hash_value_early_read;
> +
> +static int early_resume_init(void)
> +{
> + hash_value_early_read = read_magic_time();
> + return 0;
> +}
> +
> +static int late_resume_init(void)
> +{
> + unsigned int val = hash_value_early_read;
> + unsigned int user, file, dev;
> +
> + user = val % USERHASH;
> + val = val / USERHASH;
> + file = val % FILEHASH;
> + val = val / FILEHASH;
> + dev = val /* % DEVHASH */;
> +
> + printk(" Magic number: %d:%d:%d\n", user, file, dev);
> + show_file_hash(file);
> + show_dev_hash(dev);
> + return 0;
> +}
> +
> +core_initcall(early_resume_init);
> +late_initcall(late_resume_init);
> diff --git a/include/asm-generic/rtc.h b/include/asm-generic/rtc.h
> index cef08db..4087037 100644
> --- a/include/asm-generic/rtc.h
> +++ b/include/asm-generic/rtc.h
> @@ -114,6 +114,7 @@ #endif
> /* Set the current date and time in the real time clock. */
> static inline int set_rtc_time(struct rtc_time *time)
> {
> + unsigned long flags;
> unsigned char mon, day, hrs, min, sec;
> unsigned char save_control, save_freq_select;
> unsigned int yrs;
> @@ -131,7 +132,7 @@ #endif
> if (yrs > 255) /* They are unsigned */
> return -EINVAL;
>
> - spin_lock_irq(&rtc_lock);
> + spin_lock_irqsave(&rtc_lock, flags);
> #ifdef CONFIG_MACH_DECSTATION
> real_yrs = yrs;
> leap_yr = ((!((yrs + 1900) % 4) && ((yrs + 1900) % 100)) ||
> @@ -152,7 +153,7 @@ #endif
> * whether the chip is in binary mode or not.
> */
> if (yrs > 169) {
> - spin_unlock_irq(&rtc_lock);
> + spin_unlock_irqrestore(&rtc_lock, flags);
> return -EINVAL;
> }
>
> @@ -187,7 +188,7 @@ #endif
> CMOS_WRITE(save_control, RTC_CONTROL);
> CMOS_WRITE(save_freq_select, RTC_FREQ_SELECT);
>
> - spin_unlock_irq(&rtc_lock);
> + spin_unlock_irqrestore(&rtc_lock, flags);
>
> return 0;
> }
> diff --git a/include/linux/resume-trace.h b/include/linux/resume-trace.h
> new file mode 100644
> index 0000000..e2e1e14
> --- /dev/null
> +++ b/include/linux/resume-trace.h
> @@ -0,0 +1,21 @@
> +#ifndef RESUME_TRACE_H
> +#define RESUME_TRACE_H
> +
> +struct device;
> +extern void set_trace_device(struct device *);
> +extern void generate_resume_trace(void *tracedata, unsigned int user);
> +
> +#define TRACE_DEVICE(dev) set_trace_device(dev)
> +#define TRACE_RESUME(user) do { \
> + void *tracedata; \
> + asm volatile("movl $1f,%0\n" \
> + ".section .tracedata,\"a\"\n" \
> + "1:\t.word %c1\n" \
> + "\t.long %c2\n" \
> + ".previous" \
> + :"=r" (tracedata) \
> + : "i" (__LINE__), "i" (__FILE__)); \
> + generate_resume_trace(tracedata, user); \
> +} while (0)
> +
> +#endif
> _______________________________________________
> linux-pm mailing list
> linux-pm@lists.osdl.org
> https://lists.osdl.org/mailman/listinfo/linux-pm

--
Nigel, Michelle and Alisdair Cunningham
5 Mitchell Street
Cobden 3266
Victoria, Australia

[-- Attachment #1.2: Type: application/pgp-signature, Size: 189 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]